Skip to content

插件超时量的是挂钟:机器一忙,只花 0.1 毫秒的插件也被判超时并丢掉改写 #55

Open

Description

@tokenmp

结论

plugin.DefaultLimits() 的 50 毫秒预算,量的是挂钟(time.AfterFunc),
把「等着被调度」也算进了预算。机器一忙,插件本身只花 0.1 毫秒也会被判超时、
整条改写被丢掉。而且判超时之后没有任何地方记一笔能对上这次调用的账 ——
只在插件自己的 Warn 里写一行,那一行连 request_id 都没有。

配置里也没有把这个预算调大的路。

现网证据

本机网关上(tokenmp.service,4 核,load average 5~7),今天 13:45:42 到
15:33:24 之间 195 次:

msg=插件执行失败,已跳过 plugin=stream-usage hook=onRequest
  error="plugin: stream-usage.onRequest 执行失败: interrupted:
          plugin: 源码求值或钩子执行超过 50ms 被中断"

按插件分:test 108 次、stream-usage 87 次。
按死在哪儿分:onRequest 执行失败 129 次、解析输入失败 66 次。

两个关键点:

  1. test 插件的钩子体是 return null(cli/bin/plugins/test/plugin.js:14),
    一行代码都不干活,照样被打断 108 次。
  2. 66 次死在 解析输入失败,也就是死在 runtime.ParseJSON(input)
    (plugin/host.go:321)—— 这是宿主自己把请求体喂给运行时的开销,
    插件的钩子体还没开始跑。

复现

只按插件目录里的源码跑,不碰网关配置。同一个 test 插件、同一份 64 KiB 负载
(空闲时 0.1 毫秒的活儿),只改机器上有多少别的活在跑:

插件 test   请求体 0.06 MiB   预算 50ms   GOMAXPROCS=4
机器空闲        干扰  0   超时   0/500   最慢 1.563ms
有别的活在跑     干扰  8   超时   0/500   最慢 88.119ms
机器很忙        干扰 64   超时  12/500   最慢 423.463ms

负载再大一点就更容易:

插件 stream-usage   请求体 1.0 MiB   预算 50ms
并发  1   超时 0/200   最慢  6.621ms
并发  8   超时 0/200   最慢 33.594ms
并发 16   超时 0/200   最慢 50.634ms
并发 32   超时 0/200   最慢 96.855ms

同一个插件、同一份负载,单发从来不过 50 毫秒,一发多就过。
超时的那个数不是插件算出来的,是调度器欠它的。

为什么这是 core 的事

  • 预算定在 plugin/manifest.go:111(DefaultTimeout = 50 * time.Millisecond),
    它的说明写的是「本地改写的正常耗时在微秒级,超过这个量级的插件应当在转发路径之外
    完成」—— 说的是插件的耗时,量的却是挂钟。
  • 计时覆盖的范围比说明宽:plugin/host.go:310 的 AfterFunc 挂在 runtime.Load
    之前,所以 Load + ParseJSON + Call 全在预算里。现网那 66 次就是死在中间的
    ParseJSON 上。
  • 没有配置口子:config.Plugins 只有 Dir 与 List(config/config.go:246),
    server.BuildPlugins(server/server.go:291)直接写死
    plugin.LoadDir(cfg.Plugins.Dir, plugin.DefaultLimits())。
  • 失败不留痕:Outcome.Failures 填好了(plugin/store.go:156),但转发路径上没有
    任何一处读它
    (全仓只读点都在 plugin/plugin_test.go)。唯一的线索是
    plugin/store.go:186 那一行 Warn,它不带 request_id,所以事后拿一次调用去对,
    对不上——只能靠时间戳猜。

后果

改写失效、原样转发(plugin/store.go 头部的设计如此,本身是对的)。但:

  • stream-usage 失效 → stream_options.include_usage 没注入 → 上游可能不在流尾
    给用量。这一条我还没在本机日志里坐实(缺 prompt_tokens 的那 6 行全是上游
    超时的 channel="",跟插件没关系),所以别把它当既成事实。
  • 频率不低:两小时 195 次,而这段时间一共约 2600 次请求。

想怎么办(供讨论,不预设)

三件可以分开做:

  1. 预算该量什么:要么按 CPU 时间量(RUSAGE_SELF 或别的方式)而不是挂钟,
    要么把 ParseJSON 移出预算范围(它是宿主自己干的活,不是插件作者的代码)。
  2. 失败要能对上账:Failure 带上 request_id,或者在转发路径上读一次
    Outcome.Failures 并记进访问日志那一行。
  3. 给个口子:plugins.timeout(全局)或 plugins.list[].timeout(按插件),
    默认值是否要抬离 50 毫秒另说。

我在哪台机上测的

cli/bin/tokenmp(按 cli b1c0e83da3e2 编的,core 是 (devel) 直接编进去的)、
moejs v0.1.0-alpha.6、go1.27.2、4 核、load average 5~7。
探针是按插件目录里的源码直接调的(plugin.LoadFile + Instance.Call),
没走网关。

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions