fix(billing/quota): 探测预算用 os.clock 是 CPU 时间,12 秒预算从未生效

## 现象

线上 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,或者给已知死掉
的上游走缓存而不是每次重探。都是参数与策略选择,不是结构缺陷,留给下一步。
This commit is contained in:
JianFeeeee
2026-10-04 21:56:10 +08:00
parent 360a2a8644
commit e5af4ec34c
2 changed files with 119 additions and 12 deletions

View File

@ -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)
}

View File

@ -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