審查我改的程式這件事,我把主力交給跑在小型機器上的一條 lane。從某個時間點開始,這條 lane 的 review 偶爾逾時。一開始偶爾發生,後來大 PR 必中。我花了一段時間才把原因弄清楚。
我最初的猜測最直接:小機器負荷太重、網路不穩、provider 那邊降速。猜哪一個都合理,測起來也都不難。
但數據不站在我這邊。我把逾時的案子攤開來對照,發現逾時與主機的關聯根本不相關:同一台主機,文件(docs)類的 review 幾十秒就完成,一次逾時都沒有。逾時的案子全部有一個共同點:它們的 diff 是密集的程式碼改動。一個 +867 行的 Python diff 跑了 527 秒,超時的全是 +1040 行那個量級的大 diff。同一台主機、同一條網路,按 diff 內容的密度分成兩個世界。
第一個根因確認:不是主機也不是網路。是 provider 視窗大小。這條 lane 能吃到的大約 583 秒,密集的大 diff 需要接近甚至超過這個窗口。逾時不是故障,是資源的上限被踩到。要縮短它,唯一健康的路是控制每次送審的份量,把大 PR 拆開,密集的程式碼大約壓在六百行以內。
同時有第二個問題。有些大 diff 的 review 沒有逾時,卻回報另一個錯誤:artifact 無效。這次我猜的方向和第一個根因同族:產出那側又壞了,或上拋的檔案格式變了。也錯。
事實是什麼?這次的關鍵在某個工具上的內部行為。我的審查系統有個環節用一套 CLI 的匯出功能拿 run 的完整紀錄,那個 CLI 是打包編譯的版本。打包的 runtime 有一個不顯眼的上限:把輸出導向 pipe 時,超過 64 KB 就會被內部的退出函數提前截斷。大 run 的紀錄比 64 KB 大得多,於是被無聲地切掉,下游拿到的就是一份無效的殘片。修法很樸素:不經 pipe,把輸出寫進檔案再讀檔。
這個根因我在臆測的時候完全沒有方向,真正抓到它的,不是更多次的猜測,而是我多加了一個攤位:每個 review 都有各自的 diagnostics 檔,詳記每個階段的耗時、每個環節的位元數、以及來自每個 provider 嘗試的錯誤摘記。兩個根因先後被它抓出來之前,我是拿不到這種紀錄的。
猜根因的自然反射是認為猜錯就是浪費。這個案子讓我不這樣想:猜測被立即反駁,也是進展。主機與網路這個方向,正是靠 docs 快、大 diff 慢的對照數據被一擊排除的;如果我不猜、也不去比對,我會往那個方向白修一陣子。
但我給自己立了一個流程:動手修之前,先把錯誤碼分開歸檔。review-provider-timeout 與 review-provider-artifact-invalid 在帳面上就一直是兩個不同的錯誤,各自對上真實根因前的所有跡象,全部攤開比對。猜錯的紀錄會留下來,這是猜錯的價值。
調查途中發現一個更有意思的行為。我從筆電去操作遠端的 run,中途 ssh 斷了,我預期那個 run 會停。它沒有,它繼續跑到完成。原因是一個細節:沒有 terminal 的情況下,遠端 process 不會收到斷線的訊號,它會變成孤兒繼續跑,直到自己結束。孤兒 process 卡在容器裡,比原設想的清理時限更長。
診斷資料在,反應時間仍取决於人。大 diff 逾時,還是要等人去翻檔案才能定位;我還沒有把「逾時發生時,診斷摘要自己浮上來」做進 runner。
今天為了拆異象配了診斷用的檔案,之後我發現:裝好的工具也可能根本沒在運轉,默默空轉三週。明天講這個。