一次 SSE 首事件延迟 5 秒的排查复盘：问题不在缓存，而在 Flush 能力丢失

背景

最近在排查一个 AI 流式输出的问题时，客户端反馈了一个很明显的异常现象：

  • IM 占位消息很快就到了前端
  • 但 SSE 的第一条事件要过大约 5 秒才到
  • 一旦第一条事件到了，后续一整串事件又在几十毫秒内快速到齐

这个现象非常不像“正常流式输出”，更像是某一层把本该实时下发的 SSE 数据攒住了，最后一次性推给客户端。

问题最终定位在 ax-im-gateway 这个网关里，而且根因并不是传统意义上的“缓存开关”或者 gzip，而是一个更隐蔽的问题：

自定义中间件包装了 ResponseWriter，但没有透传 Flush 能力，导致标准库本该实时刷新的 SSE 响应退化成了“缓冲后再发”的伪流式。

这篇文章把这次事件完整整理出来，包括：

  • 现象为什么一眼就该怀疑“伪流式”
  • 为什么最开始会误以为是缓存
  • Go 标准库 ReverseProxy 是如何处理 SSE 的
  • 为什么一个没实现 Flush 的包装器会让实时流失效
  • 修复方案是什么
  • 这类问题以后应该怎么快速定位

问题现象

客户端给出的关键日志如下：

text
15:22:34.140 [AI][请求开始]
15:22:34.629 占位消息已经通过 IM 推到前端了
15:22:39.295 [SSE][Response]，距离请求开始 5155ms
15:22:39.296 [SSE][FirstDataLine]，距离请求开始 5156ms
15:22:39.298 [AI][SSE首事件收到]，距离请求开始 5158ms
15:22:39.304 [AI][SSE事件准备推送]，距离请求开始 5164ms

从这几行可以直接得出几个结论：

  1. 前端主进程在“收到第一条 SSE”之后，处理得非常快。
  2. SQLite 落库也不是瓶颈，只有几毫秒。
  3. 最主要的耗时几乎全部集中在：
text
请求开始 -> SSE 响应建立 / 第一条 data 到达

这意味着问题大概率不在客户端渲染层，而在服务端、网关、代理、中间件这些“响应还没真正送到客户端之前”的链路上。

为什么这个现象很像“伪流式”

正常的 SSE 流式输出，时间分布一般是这样的：

  1. 客户端发起请求
  2. 服务端很快返回响应头
  3. 很快收到第一条 data: ...
  4. 后续事件按业务进度逐步到达
  5. 最后响应结束

也就是说，正常流式的视觉特征通常是：

  • Response 很早建立
  • FirstDataLine 很早到
  • 后续事件是拉开时间分布的
  • ResponseEnd 在最后

但这次日志的特征刚好相反：

  • Response 很晚才到
  • FirstDataLine 也很晚才到
  • ResponseEnd 几乎和 FirstDataLine 同时出现
  • 后续一串事件在本地几十毫秒内被迅速消费完

这通常说明：

数据并不是一边生成一边发，而是被某一层先攒住了，等到后端 run 基本结束或缓冲触发后，才一次性吐给客户端。

也正因为这个特征，我们一开始把排查重点放在了三个方向：

  1. 后端服务根本没有真正流式输出
  2. 代理/网关把 text/event-stream 缓冲了
  3. 服务端虽然写了 SSE，但没有及时 flush

第一反应为什么会怀疑“缓存”

只看表面现象，很多人第一反应都会怀疑：

  • Nginx 开了 proxy_buffering
  • 网关有 response cache
  • 某层 gzip 或 chunk 聚合把内容攒住了

这次一开始也一样，第一猜测就是：

会不会是网关做了响应缓存，导致 SSE 没有实时透传？

这个怀疑并不奇怪，因为“响应不是实时到，而是后面一下子到”的表象，确实很像缓存。

但随着代码排查深入，问题逐渐变得清晰：

  • 代码里没有显式的 response cache 逻辑
  • 也没有看到 gzip / compress / buffering 相关中间件
  • 实际用的是 Go 标准库的 httputil.ReverseProxy

而标准库的 ReverseProxy，对 SSE 是有专门处理的。

这意味着：

如果 SSE 没能实时下发，问题不一定是缓存，还有一种非常容易忽略的可能：流式刷新的能力在中间层被“包没了”。

网关的实际请求链路

这次问题出在 ax-im-gateway 的请求链路上。

入口大致是：

text
客户端请求
  -> Gateway.ServeHTTP
  -> 全局中间件链
  -> request_logging 中间件包装 ResponseWriter
  -> 代理层 ProxyHandler
  -> httputil.ReverseProxy
  -> 后端 AI 服务

关键代码点有两个：

1. request_logging 中间件会包装 ResponseWriter

位置：

  • internal/middleware/request_logging.go

核心逻辑大致是：

go
responseRecorder := &ResponseRecorder{
    ResponseWriter: w,
    statusCode:     200,
    body:           &bytes.Buffer{},
}

next.ServeHTTP(responseRecorder, r)

它的初衷很正常：

  • 记录状态码
  • 记录响应体
  • 最后输出请求/响应日志

也就是说，它相当于在原始 ResponseWriter 外面套了一层“观察器”。

2. 代理层使用的是标准库 ReverseProxy

位置：

  • internal/proxy/proxy.go

核心逻辑是：

go
proxy := &httputil.ReverseProxy{
    Director:       ...,
    Transport:      p.transport,
    ModifyResponse: p.modifyResponse,
    ErrorHandler:   p.errorHandler,
}

proxy.ServeHTTP(w, r)

理论上，这一层本来就应该支持 SSE 透传。

所以真正的问题就变成了：

ReverseProxy 本来支持流式，那它为什么在这里失效了？

Go 标准库是如何处理 SSE 的

这是这次问题里最关键的原理点。

Go 标准库的 httputil.ReverseProxy 在转发响应时，会根据响应头判断这是不是一个流式响应。

对于 text/event-stream，它会直接认为这是 SSE，并采用“立即刷新”的策略。

标准库里的关键逻辑大致是：

go
func (p *ReverseProxy) flushInterval(res *http.Response) time.Duration {
    resCT := res.Header.Get("Content-Type")

    if baseCT, _, _ := mime.ParseMediaType(resCT); baseCT == "text/event-stream" {
        return -1 // 负值表示每次写完立即 flush
    }

    if res.ContentLength == -1 {
        return -1
    }

    return p.FlushInterval
}

也就是说，标准库并不会傻傻地把 SSE 当成普通响应处理，而是知道：

“这是流式响应，我应该边拷贝边 flush。”

继续往下看它的实现，会发现 ReverseProxy 在执行刷新的时候，用的是：

go
http.NewResponseController(dst).Flush()

这里的关键字是：ResponseController。

ResponseController 到底在做什么

ResponseController 是 Go 标准库提供的一层能力探测器。

它会拿到当前的 ResponseWriter，然后尝试判断这个 writer 是否支持：

  • Flush
  • Hijack
  • deadline
  • 其他底层控制能力

它的逻辑可以理解成：

  1. 先看你当前这个 writer 自己会不会 Flush
  2. 如果不会，看你能不能 Unwrap()，拿到底层 writer
  3. 再去底层继续找会不会 Flush
  4. 如果一路都找不到，就返回 feature not supported

这点非常关键，因为它意味着：

只要你中间自己包了一层 ResponseWriter，你就必须负责把底层的流式能力透传出去。

否则标准库只能看到你这一层“壳”，看不到里面真正支持 flush 的底层 writer。

真正的根因：自定义包装器把 Flush 能力弄丢了

问题最后就落在 ResponseRecorder 这个类型上。

修复之前，它大概是这样的：

go
type ResponseRecorder struct {
    http.ResponseWriter
    statusCode int
    body       *bytes.Buffer
}

func (rr *ResponseRecorder) WriteHeader(statusCode int) {
    rr.statusCode = statusCode
    rr.ResponseWriter.WriteHeader(statusCode)
}

func (rr *ResponseRecorder) Write(data []byte) (int, error) {
    rr.body.Write(data)
    return rr.ResponseWriter.Write(data)
}

看起来没问题，但实际上缺了两个决定性的方法：

  • Flush()
  • Unwrap()

这就导致一个很隐蔽的问题：

表面上

它会写数据，也会回写状态码。

实际上

它已经不再是一个“完整意义上的可流式 writer”了。

对于标准库来说，这个对象只会：

  • Write
  • WriteHeader

但不会：

  • Flush

于是 ReverseProxy 虽然知道这是 SSE，也确实想“立刻 flush”，可它拿到的是一个不会 flush 的包装器。

结果就是：

  • 后端已经写出了 SSE 事件
  • ReverseProxy 也在转发
  • 但是“立刻把数据冲给客户端”这个动作做不出来
  • 数据只能滞留在后续缓冲链路里
  • 等到响应快结束、缓冲区满足条件、或者连接收尾时，再一次性推给客户端

这就是为什么客户端会看到：

  • 第一条事件迟迟不来
  • 一旦来了，后面又在几十毫秒内全部到齐

为什么这不是“缓存”，但看起来很像缓存

这个问题特别容易误导人的地方就在这里。

严格来说，它不是传统意义上的 response cache：

  • 不是 Redis 缓存
  • 不是 Nginx proxy_cache
  • 不是应用层主动把整个响应先读完再返回

但它表现出来的效果，和缓存/聚合非常像：

  • 数据没有及时到客户端
  • 客户端看到的是“延迟一段时间后批量到达”

所以更准确的说法应该是：

这不是缓存开关导致的响应缓存，而是因为流式 flush 能力丢失，导致响应在传输链路里发生了非预期的缓冲和聚合。

换句话说：

根因是“不会 flush”，结果表现成了“像被缓存了一样”。

修复方案

修复方案非常简单，但必须准确。

核心思路是：

既然中间件包装了 ResponseWriter，那就必须把底层的流式能力透传回去。

所以最终补了两个方法：

go
func (rr *ResponseRecorder) Flush() {
    if flusher, ok := rr.ResponseWriter.(http.Flusher); ok {
        flusher.Flush()
    }
}

func (rr *ResponseRecorder) Unwrap() http.ResponseWriter {
    return rr.ResponseWriter
}

这两个方法分别解决两个问题：

1. Flush()

如果外层有人直接把这个 recorder 当成 http.Flusher 来用，它现在可以把 flush 操作继续透传到底层。

2. Unwrap()

即使外层不是直接做类型断言，而是通过 http.NewResponseController(...) 来逐层向下探测能力，也能继续找到真正支持 flush 的底层 writer。

也就是说，修复之后这层包装器就不再是一个“功能残缺的壳”，而是一个既能记录响应信息，又不会破坏流式能力的透明包装器。

为什么代理层的另一个包装器也一并修了

除了 request_logging 里的 ResponseRecorder，internal/proxy/proxy.go 里还有另一个 ResponseRecorder，主要给熔断逻辑记录状态码。

虽然这次问题主要暴露在 request_logging 上，但那个包装器也有同样的问题：

  • 会 Write
  • 会 WriteHeader
  • 不会 Flush
  • 也没有 Unwrap

这就意味着：

只要以后某条流式链路走到这个包装器，也可能再次出现同类问题。

所以这次一起修掉，避免将来再踩同一个坑。

我们是如何验证根因的

这次没有靠“拍脑袋修一下试试”，而是先写了回归测试把问题钉死。

思路很简单：

如果一个包装器是合格的流式 ResponseWriter，那么下面这段代码应该成立：

go
if err := http.NewResponseController(recorder).Flush(); err != nil {
    t.Fatalf("expected wrapped response writer to support flush, got %v", err)
}

修复前，测试失败，错误是：

text
feature not supported

这说明标准库在这个包装器上确实找不到 Flush 能力。

修复后，测试通过，并且能证明 flush 已经真实透传到底层 httptest.ResponseRecorder。

这比单纯“改完再跑一下看看感觉对不对”要可靠得多。

修复后为什么效果会立刻恢复正常

修复后，链路重新变成：

  1. 后端服务写出 SSE 事件
  2. ReverseProxy 识别出 text/event-stream
  3. 每次写完都调用 Flush
  4. Flush 经由包装器透传到底层真实 ResponseWriter
  5. 数据立刻刷到客户端

于是客户端看到的行为就重新符合真正流式的特征：

  • 响应头更早建立
  • 第一条 SSE 更早到达
  • 后续事件按业务进度逐步到达
  • 不再出现“前面 5 秒没动静，后面一瞬间全到”的现象

这次事件的一个重要经验：会写 Write，不等于支持流式

这是我觉得这次事件里最值得单独拿出来讲的一点。

很多人在写自定义 ResponseWriter 包装器的时候，第一反应都是：

  • 实现 WriteHeader
  • 实现 Write
  • 状态码和 body 记下来
  • 完成

但这其实只适用于普通响应。

如果你的链路里存在下面这些场景：

  • SSE
  • WebSocket / Hijack
  • HTTP streaming
  • 文件下载
  • 长连接分块响应

那么一个合格的包装器通常还必须考虑透传这些能力：

  • http.Flusher
  • http.Hijacker
  • http.Pusher
  • io.ReaderFrom
  • Unwrap()

否则你虽然“功能上看起来能跑”，但实际上已经悄悄把底层协议能力削弱了。

这类问题往往不会在普通接口里暴露，只有到流式、长连接、升级协议这些场景才突然炸出来。

以后遇到 SSE 不流式，应该优先检查什么

这次排查之后，我给自己总结了一个很实用的检查顺序。

如果以后再遇到“首条 SSE 很慢”或者“看起来像伪流式”的问题，我会先按下面顺序查：

1. 先看时间分布是不是典型的“伪流式”

重点看四个时间点：

  • 请求开始
  • Response 建立
  • FirstDataLine 到达
  • ResponseEnd

如果出现这种形态：

  • Response 很晚
  • FirstDataLine 很晚
  • ResponseEnd 几乎同时到

那就优先怀疑：

  • 中间层缓冲
  • flush 丢失
  • 服务端根本没实时写出

2. 查服务端是否真的边生成边写

看后端：

  • 有没有在 run 刚启动时就写 RUN_STARTED
  • 写完后有没有显式 flush
  • 框架是否对流式响应做了特殊处理

3. 查代理/网关是否有 buffering / gzip / 聚合

尤其是：

  • Nginx proxy_buffering
  • Ingress
  • API Gateway
  • 自定义中间件

4. 重点检查自定义 ResponseWriter 包装器

如果项目里有任何类似下面的代码：

go
type MyResponseWriter struct {
    http.ResponseWriter
    ...
}

那就一定要问自己：

  • 它有没有实现 Flush？
  • 有没有实现 Unwrap？
  • 有没有破坏 Hijack / Pusher 等能力？

这一条非常重要，因为这类问题太隐蔽了。

一句话总结这次根因

如果只用一句话总结这次问题，我会这样写：

这次 SSE 首事件延迟并不是因为网关开启了缓存，而是因为请求日志中间件包装了 ResponseWriter 却没有透传 Flush 能力，导致 Go 标准库 ReverseProxy 本应实时刷新的 SSE 响应退化成了“缓冲后再发”的伪流式。

最后的经验

这次问题给我的最大提醒是：

在 Go 里，自定义包装 ResponseWriter 不是只实现 Write 和 WriteHeader 就完事了。

如果项目里有流式响应、SSE、WebSocket、长连接、协议升级这些场景，那么任何一层包装器都必须非常谨慎。你包装的不是一个普通对象，而是一个承载了底层协议能力的接口。

一旦这些能力没有被完整透传，问题表面上可能看起来像：

  • 缓存
  • 网络抖动
  • 上游慢
  • 客户端处理慢

但真正的根因，可能只是一个很小、很不起眼的方法没有实现。

这类 bug 最难的地方，不是修，而是看见。

附：本次修复的核心代码

internal/middleware/request_logging.go

go
func (rr *ResponseRecorder) Flush() {
    if flusher, ok := rr.ResponseWriter.(http.Flusher); ok {
        flusher.Flush()
    }
}

func (rr *ResponseRecorder) Unwrap() http.ResponseWriter {
    return rr.ResponseWriter
}

internal/proxy/proxy.go

go
func (rr *ResponseRecorder) Flush() {
    if flusher, ok := rr.ResponseWriter.(http.Flusher); ok {
        flusher.Flush()
    }
}

func (rr *ResponseRecorder) Unwrap() http.ResponseWriter {
    return rr.ResponseWriter
}

这两个改动本身很小，但它修复的是整个流式响应链路最关键的实时性问题。