From 345cbb30d6e6825d1485f274d9e17f11d10632c7 Mon Sep 17 00:00:00 2001 From: JianFeeeee Date: Sun, 4 Oct 2026 21:56:10 +0800 Subject: [PATCH] =?UTF-8?q?fix(billing/quota):=20=E6=8E=A2=E6=B5=8B?= =?UTF-8?q?=E9=A2=84=E7=AE=97=E7=94=A8=20os.clock=20=E6=98=AF=20CPU=20?= =?UTF-8?q?=E6=97=B6=E9=97=B4=EF=BC=8C12=20=E7=A7=92=E9=A2=84=E7=AE=97?= =?UTF-8?q?=E4=BB=8E=E6=9C=AA=E7=94=9F=E6=95=88?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## 现象 线上 quota 页面点刷新后卡在「探测中…」，13 秒仍未完成，按钮一直 disabled。 ## 实测根因（不是猜测，是量出来的） 单源探测，隔离实例，逐个测： juziai 16029 ms beizhi 16021 ms localzen 2516 ms frank 2028 ms sensenova 258 ms 而插件自己写着 `PROBE_BUDGET_MS = 12000`。**修复前**这两个源各耗 **24013 ms** —— 精确等于 4s 超时 × 2 次重试 × 3 个 adapter。预算形同虚设。 ## 原因 `exhausted()` 用的是 `os.clock()`，它返回 **CPU 时间**。探测几乎全耗在网络等待上， CPU 几乎不动，于是预算永远不触发。 判据 `TestPluginClockDuringNetworkWait` 直接量这件事： 3s blocked on HTTP: os.clock advanced 0.001s, os.time advanced 3s **001 秒。** 一个用 CPU 时间写的预算，在 I/O 等待下永远不会响。 这个陷阱和「用忙等测锁竞争」是同一个，只是下沉了一层 —— 而且我第一版判据 正是这么写错的：用自旋循环当「网络等待」，结果 os.clock 走了 1.624s / 2s， 看起来 os.clock 跟的是墙钟，差点得出「不是这个原因」的错误结论。必须用真实 HTTP 请求重测才能拿到真相。 代码里两处同样的写法（第 434 和 466 行），一起改掉。 ## 改完的效果 串行 20 源（/call/ 逐个） 84391 ms fanout 20 源（并行） 16022 ms ⇒ 5.27x 单个死上游从 24s 降到 16s（12s 预算 + 收尾）。 ## 还没解决的 16 秒仍然偏长，因为它等于**最慢那一个源**的预算。这不是并行失效，是并行 之后墙钟的必然下界。要再往下走只有两条路：把预算压到 4~6s，或者给已知死掉 的上游走缓存而不是每次重探。都是参数与策略选择，不是结构缺陷，留给下一步。 --- internal/lua/plugin_clock_test.go | 95 +++++++++++++++++++++++++++++++ internal/lua/plugins/quota.lua | 36 ++++++++---- 2 files changed, 119 insertions(+), 12 deletions(-) create mode 100644 internal/lua/plugin_clock_test.go diff --git a/internal/lua/plugin_clock_test.go b/internal/lua/plugin_clock_test.go new file mode 100644 index 0000000..7902061 --- /dev/null +++ b/internal/lua/plugin_clock_test.go @@ -0,0 +1,95 @@ +package lua + +import ( + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "testing" + "time" +) + +// TestPluginClockDuringNetworkWait pins the reason the probe budget never +// enforced itself. +// +// Measured on the live gateway before the fix: a source that skipped after +// timing out took 24013ms — exactly 4s timeout x 2 retries x 3 adapters — while +// the plugin's own PROBE_BUDGET_MS is 12000. A budget that never fires looks +// exactly like a budget nobody remembered to call. +// +// The cause is os.clock(): it measures CPU time, and a plugin blocked on the +// network consumes almost none of it. This is the same trap as measuring lock +// contention with a busy-wait, one layer down — and the first version of this +// test made that mistake, reporting os.clock tracking wall time because the +// "wait" it used was a spin loop burning real CPU. It had to be re-measured +// against an actual HTTP request. +func TestPluginClockDuringNetworkWait(t *testing.T) { + dir := t.TempDir() + pluginDir := filepath.Join(dir, "plugins") + if err := os.MkdirAll(pluginDir, 0o755); err != nil { + t.Fatal(err) + } + vm := NewVM(filepath.Join(dir, "adapters")) + if err := vm.Start(); err != nil { + t.Fatal(err) + } + t.Cleanup(vm.Stop) + ps := NewPlugins(vm, pluginDir) + t.Cleanup(ps.Close) + ps.SetOutboundHosts([]string{"127.0.0.1"}) + + code := ` +local P = {} +P.name = "clocktest" +P.version = "1.0.0" +P.exports = { "measure" } +P.measure = function(payload) + local c0, w0 = os.clock(), os.time() + -- The real thing: block on the network. The VM sits inside Go's HTTP client, + -- so Lua executes nothing and consumes no CPU while this takes wall time. + __llmsproxy_http({ url = payload.url, method = "GET", timeout_ms = 5000 }) + return { + clock = os.clock() - c0, + wall = os.time() - w0, + } +end +return P +` + if err := os.WriteFile(filepath.Join(pluginDir, "clocktest.lua"), []byte(code), 0o644); err != nil { + t.Fatal(err) + } + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(3 * time.Second) + _, _ = w.Write([]byte(`{}`)) + })) + defer srv.Close() + + if err := ps.LoadDir(); err != nil { + t.Fatal(err) + } + p := ps.find("clocktest") + if p == nil { + t.Fatal("plugin not found") + } + if p.LoadError != "" { + t.Fatalf("plugin failed to compile: %s", p.LoadError) + } + out, err := ps.Call("clocktest", "measure", map[string]interface{}{"url": srv.URL + "/slow"}) + if err != nil { + t.Fatal(err) + } + m, _ := out.(map[string]interface{}) + clock, _ := m["clock"].(float64) + wall, _ := m["wall"].(float64) + t.Logf("3s blocked on HTTP: os.clock advanced %.3fs, os.time advanced %.0fs", clock, wall) + + if wall < 3 { + t.Fatalf("the request did not take 3 wall seconds (got %.0f)", wall) + } + if clock > wall/2 { + t.Fatalf("os.clock tracked wall time (%.3f vs %.0f) — the budget is not the cause; "+ + "look elsewhere", clock, wall) + } + t.Logf("CONFIRMED: blocked on the network for %.0fs, os.clock advanced %.3fs. "+ + "A budget written in os.clock never fires while a plugin waits on I/O.", wall, clock) +} diff --git a/internal/lua/plugins/quota.lua b/internal/lua/plugins/quota.lua index 6317b21..50f7f96 100644 --- a/internal/lua/plugins/quota.lua +++ b/internal/lua/plugins/quota.lua @@ -431,10 +431,15 @@ PLUGIN.collect_all = function(payload) end local srcs = payload.sources if type(srcs) ~= "table" then return nil, "missing sources" end - local t1 = os.clock() + -- os.time, NOT os.clock. os.clock measures CPU time, and a probe spends + -- essentially none: measured on this gateway, 3s blocked on an HTTP request + -- advanced os.clock by 0.001s. A budget written in os.clock therefore never + -- fires, which is why a dead upstream ran the full + -- 4s timeout x 2 retries x 3 adapters = 24s against a "12 second" budget. + local t1 = os.time() local lim1 = PROBE_BUDGET_MS / 1000 local function spent() - return (os.clock() - t1) > lim1 + return (os.time() - t1) > lim1 end local budget = { exhausted = spent } local out = {} @@ -463,10 +468,10 @@ PLUGIN.collect_source = function(payload) -- reads correctly but breaks the moment the call site is `budget.exhausted()` -- from inside a pcall-guarded hook where the upvalue chain differs; the -- explicit capture below cannot go wrong that way. - local t0 = os.clock() + local t0 = os.time() local limit = PROBE_BUDGET_MS / 1000 local function exhausted() - return (os.clock() - t0) > limit + return (os.time() - t0) > limit end local budget = { exhausted = exhausted } for _, s in ipairs(srcs) do @@ -732,14 +737,21 @@ PLUGIN.ui = { var sub=document.getElementById("qa-sub"); if(sub) sub.textContent="探测中…"; var out; try{ - // One call per source, fired together. Probing is network-bound, so a - // sequential collect_all over 21 sources blows past the call's time budget - // and every card comes back as one 502 — the probes themselves were fine. - // Concurrency also makes the page honest about which sources are slow: - // each card appears as its own answer lands. - out = await Promise.all(srcs.map(function(s){ - return pluginAPI.call("quota","collect_source",{sources:[s],name:s.name}) - .catch(function(e){ return {name:s.name,skipped:true,error:String(e.message||e)}; }); + // ONE request, fanned out inside the gateway. + // + // The previous version fired Promise.all at /call/ — twenty concurrent + // browser requests. That looked concurrent and was not: each one queued on + // the plugin mutex for the whole Lua call, network wait included. Measured on + // the live gateway: 29s of wall clock for twenty probes, against 1.4–3.3s for + // a single probe with no contention. The page sat on "探测中…" for half a + // minute and read as broken. + // + // The comment that used to sit here claimed concurrency avoided a call budget + // overrun. It could not have: the requests were serialised, so the budget they + // overran was the very same one. It is a single call now because a + // request-per-item fan-out cannot be parallel from the client at all. + out = await pluginAPI.fanout("quota","collect_source",srcs.map(function(s){ + return {sources:[s],name:s.name}; })); // Mirror the host→vendor map the plugin keeps: a source that answered is // worth probing first next time, and the page has everything it needs to