vatt'ghern jaskier's ballads
本文 1 個互動圖表在手機上以重點摘要呈現,互動版請以桌面瀏覽器開啟。

同一段沒有改過的迴圈,在同一台機器上跑 benchmark,某次跑完六十億次迭代,另一次只有三億次——整整差了二十倍。

一個 unpack,讓另一個迴圈掉回直譯器

Sander Bos 幫自己寫的 Lua 引擎 grug-for-lua 跑 benchmark 時撞見這件事。grug-for-lua 是他拿來執行 grug modding language 的實作,呼叫遊戲函式的路徑寫得很直白:一個 Entity:_run_game_fn 方法,它接收一個 vararg,再把 self.state 和那串引數原封不動轉手交給 pcall 去呼叫遊戲函式;真正把可變長度引數展開的 unpack(args),其實寫在呼叫端——self:_run_game_fn(call_expr.fn_name, unpack(args))。這段程式碼從 benchmark 第一次跑到最後一次都沒有改過,可是每次執行拿到的迭代數卻不穩定。

他一開始的懷疑很合理:程式碼裡唯一稱得上「特別」的地方,就是那個包在 pcall 裡的 unpack。順著這個懷疑追下去才發現,問題根本不在 unpack 執行的那一刻,而是落在一個完全沒碰過 pcall、也沒碰過 unpack 的函式上。

六十億次或三億次,程式碼一行都沒有動過

這個變化沒有規律可循。同一份 benchmark script,同一台機器,有時候跑完 60 億次迭代,有時候只跑完 3 億次,兩者相差 20 倍。這不是「效能偶爾抖動 5%、10%」那種噪訊等級,是快慢兩種截然不同的執行模式,而哪一種模式會出現,看起來完全隨機。

更棘手的是,這種 20 倍的落差不會穩定重現——不是每次都慢,也不是每次都快,兩種結果在不同執行之間交替出現,沒有明顯的觸發條件。如果只是單純跑一次 benchmark 看數字,很容易剛好抽到快版,得出「這段程式碼沒問題」的結論;如果剛好抽到慢版,又可能誤以為是那次執行環境不穩,重跑幾次取平均了事。兩種反應都繞過了真正的問題:程式碼本身完全沒有變過,變的是 LuaJIT 在背後做了什麼決定。

切換線性 / log 座標,看 20 倍差距怎麼被「壓平」或「攤開」 · 2 種座標

資料來源:Sander Bos, 「The LuaJIT NYI That Silently Poisoned an Unrelated Hot Loop」,grug-for-lua benchmark 的實測迭代數。

迴圈跑的是同一段 bytecode,輸入也一樣,程式碼裡沒有任何分支邏輯會產生兩種質量不同的路徑。如果變因來自輸入資料,至少還說得過去;但這裡唯一會變的,只有 LuaJIT 自己在兩次執行之間做了不同的決定。

猜測:stitch 本身要臨時掉回直譯器

最先浮上檯面的懷疑,是那個包在 pcall 裡的 unpack。LuaJIT 的 NYI(not yet implemented)清單上,unpack 被標成 stitch 類——遇到一條還沒教會怎麼編譯的 bytecode,LuaJIT 不會直接放棄整條 trace,而是做一次 stitch:先讓那條指令回到直譯器跑一次,再從下一條 bytecode 繼續錄製,變成一條新的 root trace。

這幾個詞接下來會反覆出現:NYInot yet implemented,LuaJIT 的 trace compiler 還沒教它怎麼編譯的 bytecode 或指令。stitchNYI 的一種處理方式:讓那條指令回到直譯器跑一次,再從下一條 bytecode 重新開始錄一條新的 root trace,不是整條放棄。FRAME_PCALLLuaJIT 內部用來標記「目前執行在一個 pcall 呼叫裡面」的 frame 類型,recorder 靠它才知道等下要怎麼從 pcall 返回。黑名單同一段 bytecode 反覆錄製失敗到一定次數後,LuaJIT 從此不再嘗試把它編譯進 trace,永遠留在直譯器裡跑。

Sander Bos 一開始猜的是,這個「臨時掉回直譯器」的動作本身就有代價,重複發生得夠多次,就會拖慢整段迴圈。這個猜測聽起來合理,卻被 -jv 的輸出直接推翻:他用 LuaJIT 2.1.1774896198 搭配 luajit -jv 追蹤那段 benchmark,結果 unpack 從頭到尾沒有出現在慢的那次 trace log 裡。如果問題出在 unpack 觸發的 stitch 本身,log 裡理應能看到反覆的 stitch 紀錄;看不到,代表問題根本不在 unpack 執行的那一刻。

要看清楚 trace log 裡發生了什麼,光靠肉眼掃過終端機輸出並不容易。Sander Bos 提到 luajit.me 是一個很好用的工具,介面類似 Compiler Explorer,能把 trace 輸出跟原始碼並排對照著看,NYI 的地方會直接標紅;他也提過 luajit -jdump 可以在本機做同樣的事,只是操作起來沒那麼順手。這次能這麼快釐清「unpack 沒有出現在 log 裡」這個關鍵事實,靠的正是這種工具,不是單純盯著一長串文字輸出用眼睛數。

縮小成 MRE 之後,兩次執行的 trace log 只差在收尾那幾行

把一個真實專案裡的效能異常,縮小成十幾行的最小案例,是排查這類問題最關鍵的一步——真實程式碼牽涉的函式呼叫、資料結構太多,任何 trace log 都會被大量無關的雜訊淹沒;MRE 把變因砍到只剩 pcallunpack,還有一個什麼都不做的函式,trace log 才有辦法讀。

為了把問題單獨隔離出來,他寫了一個最小可重現案例:一個什麼都不做的 empty_fn,搭配另一個 run_unpack 函式——裡面用 pcall 包住對 empty_fn 的呼叫,引數用 unpack({}) 展開。run_unpack 先跑 8 萬次當熱身,讓 JIT 有機會編譯它;熱身結束後另外開一個乾淨的迴圈,單獨計時跑 1 億次 empty_fn() 本身,這個迴圈裡完全沒有 pcall,也沒有 unpack

local function empty_fn() end

local function run_unpack()
    pcall(empty_fn, unpack({}))
end

for _ = 1, 80000 do
    run_unpack()
end

local start = os.clock()

for _ = 1, 100000000 do
    empty_fn()
end

print(os.clock() - start)

同一份程式,重複執行兩次,分別印出 0.050325 秒與 0.725689 秒,換算下來,慢版是快版的 14 倍多。計時的那個迴圈裡沒有 pcall,也沒有 unpack,兩次執行跑的是完全一樣的 1 億次 empty_fn() 呼叫——問題顯然不在計時迴圈本身,而在它前面那 8 萬次熱身跑出了什麼結果。

拖曳分隔線比較快版與慢版 trace log 的收尾 · 2 段 log

快版・0.050325 秒 [TRACE 2 pcall_mre.lua:4 return] [TRACE 3 pcall_mre.lua:22 loop]
慢版・0.725689 秒 [TRACE 2 pcall_mre.lua:4 return] [TRACE --- pcall_mre.lua:22 -- blacklisted at pcall_mre.lua:2]
資料來源:同一份 pcall_mre.lua,連續兩次執行的 luajit -jv 輸出(節錄收尾片段)。

資料來源:同一份 pcall_mre.lua,連續兩次執行的 luajit -jv 輸出(節錄收尾片段)

同一份程式碼跑兩次,快版 trace 收在已編譯的 loop,慢版收在 blacklisted——差別只在收尾那一行,前面幾乎一模一樣。

兩次 luajit -jv 的輸出,前面一大段幾乎一模一樣,都是重複出現的「NYI: return to lower frame」。差別只在收尾那幾行:快版最後編譯出一條把整段迴圈吃掉的 root trace,標成 loop;慢版最後一行卻是 blacklisted at pcall_mre.lua:2——empty_fn 所在的那段 bytecode 被整個列入黑名單,迴圈只能回去用直譯器逐行執行。

一個從沒呼叫過 pcall 的函式,為什麼會被黑名單牽連

順著 blacklisted 這幾個字回頭看,答案藏在 stitch 重新開始錄製這件事本身。trace stitching 讓錄製從失敗的那條 bytecode 之後重新開始,變成一條全新的 root trace——問題是,這條新 trace 不知道自己是從 pcall 裡面進來的。pcall 呼叫在 LuaJIT 內部會建立一個叫 FRAME_PCALL 的 frame,新錄製的 trace 完全沒有這段記憶,等到執行流程真的要返回 pcall 那一層,recording 找不到自己進來的路,直接中止,丟出「NYI: return to lower frame」。unpack 本身從來沒有真正出過事:失敗不是發生在 unpack 執行的當下,而是發生在稍後執行流程要穿過 pcall 返回的時候。

這裡有一個容易搞混的地方要先講清楚:pcall 本身不是問題,LuaJIT 完全有能力把 pcall 整段編譯進 trace;真正觸發 stitch 的,是 pcall 呼叫裡那個 unpack。混為一談的話,很容易誤以為只要程式碼裡出現 pcall 就會拖慢效能,但實際上會踩到的路窄得多——只有 pcall 裡面剛好又用了某個會 stitch 的 NYI 操作,才會走到這一步。

切換 4 個階段,看 unpack 怎麼一路連累到不相干的迴圈 · 4 個階段

觸發
pcall 裡呼叫 unpack(args) 展開可變長度引數。
LuaJIT 內部
unpack 是 NYI wiki 上的 stitch 類操作,recorder 讓這條指令回到直譯器跑一次,再從下一條 bytecode 重新開始錄製,變成一條全新的 root trace。
可觀察到的徵狀
luajit -jv 的 log 裡完全看不到 unpack 這個名字。
觸發
上一步產生的新 root trace 繼續往下錄。
LuaJIT 內部
這條新 trace 不記得自己是從 pcall 建立的 FRAME_PCALL 裡進來的,錄製時完全沒有這段上下文。
可觀察到的徵狀
目前還看不出異狀,trace log 一切正常往下走。
觸發
執行流程要從 pcall 內部返回上一層。
LuaJIT 內部
recorder 找不到自己是怎麼進到 pcall 裡的,錄製直接中止。
可觀察到的徵狀
trace log 印出「NYI: return to lower frame」,重複出現。
觸發
同一段 bytecode 反覆撞上「NYI: return to lower frame」,重試次數用盡。
LuaJIT 內部
empty_fn 自己的那段 bytecode 被列入黑名單,於是那個呼叫 empty_fn 的熱迴圈再也編譯不成 trace。
可觀察到的徵狀
trace log 收在 blacklisted at ...,連完全沒碰過 pcallunpack 的迴圈也跟著掉回直譯器逐行執行。

log 裡「沒有出現的東西」才是真正的線索。多數人排查效能問題,直覺會盯著看起來最可疑的那一行,可是這次真正有用的訊號,反而是 unpack 沒有出現在 log 裡——不出現,不代表它沒有造成影響,只是代表它的影響要晚一步、在另一個完全不同的地方才會顯形。這件事本身還不足以拖慢一段跟 pcallunpack 完全無關的迴圈。真正的關鍵在下一步:stitch 失敗到「return to lower frame」不是每次都直接放棄,LuaJIT 會重試;重試次數用完之後,LuaJIT 才會把 empty_fn 自己的那段 bytecode 列入黑名單——慢版 trace log 最後一行指的 pcall_mre.lua:2,正是 local function empty_fn() end 那一行。empty_fn 一被黑名單,那個單純呼叫它的熱迴圈就再也編譯不成 trace,只能整段掉回直譯器;而那個迴圈自己從頭到尾沒有碰過 pcall,也沒有碰過 unpack

更麻煩的是,黑名單這一步會不會發生,不是決定性的。empty_fn 最後有沒有被黑名單,取決於 benchmark loop 正式開始之前,已經有多少次 stitch attempt 跑完——這是 JIT 內部的啟發式演算法決定的,不是程式碼本身決定的。這也是為什麼同一份程式,兩次執行會擲出兩種完全不同的結果:不是玄學,是 JIT 內部一場計時競賽,誰先誰後,連寫程式的人都控制不了。

知道原因之後,修法本身不難。第一層是把 unpack 換掉:get_pcall_wrapper 會替每一種引數個數各自產生一個特化過的 wrapper 函式,把 args table 直接展開成具名引數餵給 pcall,不再呼叫 unpack,自然也不會觸發那次 stitch。這個改動進了 commit db94c5a

local loader = loadstring or load

local pcall_wrappers = {}

local function get_pcall_wrapper(arg_count)
    if pcall_wrappers[arg_count] then
        return pcall_wrappers[arg_count]
    end

    local arg_list = {}
    for i = 1, arg_count do
        arg_list[i] = "args[" .. i .. "]"
    end

    local args_str = #arg_list > 0 and (", " .. table.concat(arg_list, ", ")) or ""
    local code = string.format("return function(fn, args) return pcall(fn%s) end", args_str)

    local wrapper = loader(code)()
    pcall_wrappers[arg_count] = wrapper
    return wrapper
end

wrapper 之所以有效,關鍵在於它不再呼叫 unpack 這個函式本身——args[1]args[2] 這種直接索引 table 的寫法,LuaJIT 從一開始就能編譯,不需要透過任何 NYI 清單上的操作。換句話說,這不是繞過 stitch 的效能懲罰,而是根本不讓 stitch 有機會發生。

wrapper 只是繞開問題,沒有真正教會 LuaJIT 怎麼處理 unpack。Sander Bos 把這個教訓往上游送:他向 OpenResty 的 luajit2 fork(不是官方 LuaJIT,是 OpenResty 自己維護的分支)送出一個 pull request,標題是「perf: get unpack() out of the NYI list」,也就是 GitHub 上的 openresty/luajit2 PR #269。PR 裡新增了一個 recff_unpack 函式,直接教 trace recorder 怎麼把 unpack 編譯進 trace,不必再靠 stitch 繞路。

recff_unpack 要顧的細節,比表面上看起來瑣碎。這些防呆對應到 unpack 真實的呼叫方式:unpack(t) 只給一個 table,start、end 用預設值;但 Lua 也允許寫成 unpack(t, i, j),自己指定要展開哪個範圍。引數不是 table,得先擋下來,不能假裝繼續編譯;ij 不是常數的話,還得另外檢查陣列長度,確保不會展開到範圍外——程式碼裡的註解寫得很直接:「Guard the length, since it wasn't given as a constant」。

他寫了 30 個測試確認 recff_unpack 不會再觸發 stitch、丟出 NYI,或被黑名單,後來用 unimut 做 mutation testing,又多抓出 2 個原本 30 個測試沒覆蓋到的邊界情況。mutation testing 找出來的這 2 個邊界情況,傳統的行覆蓋率或分支覆蓋率量測不到——它們考的不是「這段程式碼有沒有被執行過」,而是「如果這段邏輯被悄悄改錯,測試會不會發現」。unimut 的做法是有系統地改動 recff_unpack 的邏輯,再檢查測試套件會不會抓到每一次改動;照出來的正是行覆蓋率、分支覆蓋率這類量測本身照不出的缺口。

這個 PR 修的範圍其實很窄。Sander Bos 自己也承認:幾乎沒有人特別去用 OpenResty 的 luajit2 fork,更多人是把某個版本的 LuaJIT 內嵌進自己的程式裡,從此不再升級。就算這個 PR 合併,wrapper 這個 workaround 也不會退場——對大多數人來說,能實際用上的解法,可預見的未來裡還是 wrapper,不是編譯器修好。

這次調查裡還撞見另一個 NYI,性質不一樣,拿來對照剛好能看出「stitch 類」和「硬 NYI」的差別。在迴圈裡面定義閉包——每次迭代都寫一次 local function nested() end 再呼叫它——會踩到 FNEW(function new)這個 bytecode。這是一個硬 NYI,不會 stitch,每次踩到都直接掉回直譯器逐行跑那次迭代。把 nested 搬到迴圈外面定義,前後對照,效能落差是 60 倍。

原文對 FNEW 只講到這裡:recorder 一碰到它,錄製就直接中止,NYI wiki 上這條 bytecode 的「Compiled?」欄位寫的是 no。至於為什麼它連 stitch 都做不到,原文沒有說明;合理的推測是:每次迴圈跑到 local function nested() end,配置出來的都是一個全新的閉包物件,trace compiler 沒有一個固定不變的目標可以編譯——stitch 至少還能先讓那一步退回直譯器、再從下一步繼續錄,硬 NYI 連這個折衷都沒有,只能整次迭代都留在直譯器裡跑。原文也順帶提了一句:理論上 LuaJIT 有機會把這個閉包配置最佳化掉,就像它已經對 table 做的那樣——靠的是 allocation sinking 這個既有的最佳化;但那終究只是「理論上」,FNEW 目前就是不折不扣的硬 NYI。

情境 NYI 類型 效能落差 判定依據
grug-for-lua 熱迴圈(真實工作負載)stitch → 黑名單20 倍60 億次 vs 3 億次迭代
pcall + unpack MRE(精簡重現)stitch → 黑名單14 倍多0.050325 秒 vs 0.725689 秒
迴圈內定義 closure(FNEW)硬 NYI(不 stitch)60 倍搬到迴圈外定義前後對照
資料來源:同一篇文章裡三個各自獨立量測的情境;效能落差為文中直接給出或由原始數字換算所得。

從 20 倍的迭代數落差,到一個埋藏在 pcall 返回路徑裡的黑名單,中間繞了不少路——先是排除了最直覺的懷疑(stitch 本身很貴),再靠 MRE 把變因砍到最少,才找到真正的觸發鏈。這條路徑本身,比修法還值得記住:光靠讀程式碼找不出這個問題,因為程式碼裡沒有任何一行是錯的;只有把 trace log 攤開來看,才看得見 LuaJIT 在背後做了什麼決定。三個案例擺在一起看,共通點只有一件事:效能問題沒有出現在寫壞的那一行,而是出現在完全不相干的地方。

Sander Bos 後來把這個檢查寫進 CI 的 build.yml,讓 benchmark 跑在 luajit -jv 底下:把輸出存下來,先過濾掉「NYI: return to lower frame」這一行——它本身是 stitch 正常的中繼過程,不過濾掉會製造一堆假警報——剩下的內容裡只要還看得到 NYI 或 blacklisted 字樣,就讓 build 直接失敗,不必等到某次執行剛好踩到門檻才被人發現。

# 過濾掉已知會出現、不代表出事的那一行
CLEANED_LOG=$(sed '/NYI: return to lower frame/d' luajit.log)

if echo "$CLEANED_LOG" | grep -q 'NYI'; then
    echo "ERROR: Unexpected NYI detected in LuaJIT trace output" >&2
    echo "$CLEANED_LOG" | grep 'NYI' >&2
    exit 1
fi

if echo "$CLEANED_LOG" | grep -q 'blacklisted'; then
    echo "ERROR: Blacklisted function detected in LuaJIT trace output" >&2
    echo "$CLEANED_LOG" | grep 'blacklisted' >&2
    exit 1
fi

這也是文章標題裡「silently」這個字要強調的重點:黑名單這一步不會丟出任何錯誤、不會讓程式當掉,甚至不會出現在一般的錯誤訊息或 log 等級裡——它只是讓某段程式碼從此以後都用直譯器跑,效能悄悄變差,如果沒有專門去看 trace log,可能永遠不會發現。這正是 tracing JIT 這類技術共同的風險:效能問題不一定出現在你猜的那個地方。一段迴圈本身寫得再乾淨,只要它呼叫到的某個函式被列入黑名單,它自己就會跟著再也編譯不成 trace,效能就這樣無聲無息地掉下去,而且不會有任何 exception 或錯誤訊息提醒你。

拖曳看調查走過的 7 步,從撞見落差到送出上游 PR · 7 個步驟

步驟 1・撞見:grug-for-lua benchmark 時而跑完 60 億次迭代,時而只有 3 億次,程式碼沒有變動。
資料來源:同一篇文章的敘事順序,整理成七個轉折點。

下次先查:追蹤 tracing JIT 的效能異常,不能只盯著看起來慢的那段程式碼——真正的病灶常常在別處,先查 trace log 裡有沒有 NYI 或 blacklisted,比對著寫壞的那一行用直覺猜,可靠得多。