用 SQL 找出缓慢的 Go 请求：使用 gospan 将 net/http 的跨度保存到 SQLite

Go API 通常会在几毫秒内响应，但有些请求却需要 40 毫秒。查看日志可以确认延迟，却无法得知这些时间究竟花在了数据库查询、渲染还是外部调用上。

一种办法是引入链路追踪基础设施。不过，如果问题局限在单个进程内，一个 SQLite 文件或许就足够了。

akmadian/gospan 可以记录嵌套的跨度（span），并将其写入 SQLite 或 log/slog。为 net/http 处理器添加埋点、运行工作负载，再查询生成的文件，就能找出缓慢的操作及其相关输入。

它的实用之处在于，将父子关系、耗时和属性组合起来，存入可用普通 SQL 查询的表中。不过，由于记录是异步进行的，事件可能会被丢弃。

本文基于所提供的 gospan v0.1.0 调研资料，其验证日期为 2026 年 10 月 7 日。下文的测量数据均来自该调研，并非为撰写本文另行运行所得。README 将文件格式定义为保持不变的契约，但 Go API 在 1.0 之前仍可能发生变化。

适用于调查范围局限在单个进程内的情况#

gospan 适合用于范围明确的调查，例如：“这个程序中的哪项操作拖慢了请求？”

其核心部分使用 Go 标准库。SQLite 接收端使用纯 Go 驱动 modernc.org/sqlite。在所提供的验证中，示例使用 CGO_ENABLED=0 构建，无需收集器或代理。

它不具备跨进程传播上下文的功能。因此，对其他服务的 HTTP 调用不会自动延续同一条追踪。如果你想跨多个服务追踪请求，这一限制就很重要。

与 OpenTelemetry 的比较也需要准确。OpenTelemetry SDK 同样可以在没有收集器的情况下运行，所需的基础设施取决于导出器和部署配置。这里 gospan 的吸引力在于，它可以将本地埋点直接衔接到可查询的 SQLite 文件生成流程。

创建文件，并在请求入口添加埋点#

验证时使用的模块如下：

snippet.txt

github.com/akmadian/gospan v0.1.0
github.com/akmadian/gospan/sqlite v0.1.0

验证所用的 gospan 模块要求 Go 1.25.0。复现本例时，请固定版本。

在应用启动时，仅初始化一次接收端。

snippet.txt

sink, err := sqlite.New("traces")
if err != nil {
    log.Fatal(err)
}

tracer, err := gospan.New(sink)
if err != nil {
    log.Fatal(err)
}

gospan.SetDefault(tracer)

默认情况下，接收端会为每次运行创建单独的文件。文件位置可通过 sink.Path() 获取。

在请求入口创建根跨度，并将返回的上下文传给处理器。

snippet.txt

func traced(route string, next http.HandlerFunc) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx, span := gospan.Start(
            r.Context(),
            "http.request",
            slog.String("http.method", r.Method),
            slog.String("http.route", route),
        )
        defer span.End()

        next(w, r.WithContext(ctx))
    })
}

调用 r.WithContext(ctx)，会为处理器内部的操作设置父跨度。如果使用原始请求上下文启动子跨度，就会丢失这一父子关系。

请保持跨度名称固定。例如，名称使用 db.query，将表名、标识符和查询类别存入属性。如果把每个用户的 ID 都放进名称，就会让内存聚合中的类别数量无谓增加。

为有优化价值的操作添加跨度#

在数据库辅助函数中，可以记录输入和错误。

snippet.txt

func loadUser(ctx context.Context, id int) error {
    ctx, span := gospan.Start(
        ctx,
        "db.query",
        slog.String("db.table", "users"),
        slog.Int("db.id", id),
    )
    defer span.End()

    err := queryUser(ctx, id)
    if err != nil {
        span.Fail(err)
    }
    return err
}

Fail 只记录结果，不会结束跨度。请保留通过 defer 调用的 End。

通过 errors.Is 匹配到 context.Canceled 或 context.DeadlineExceeded 的错误会被标记为 canceled，其他错误则标记为 error。因此，超时的依赖调用和包含该调用的 HTTP 请求可以记录不同的结果。例如，子跨度被视为已取消，而请求由于返回了 502，被记录为错误。

对于行数等事后才知道的信息，请使用 SetAttrs。在 End 之后进行的修改不会生效。

对于没有子跨度的小型操作，可以使用写法更简短的 Track。

snippet.txt

func checkCache(ctx context.Context) {
    defer gospan.Track(ctx, "cache.lookup")()
    // キャッシュを検索する。
}

Track 不会返回包含该跨度的上下文。如果需要让后续操作成为子跨度，请使用 Start。

关闭应用时，应先停止接收请求，等待正在运行的处理器完成，再使用合适的上下文调用 tracer.Close。关闭过程会处理队列中的事件，并执行最后一次刷新。

准备一个原因已知的工作负载#

在所提供的实验中，使用了 8 个并发工作协程，向以下端点共发送了 300 个请求。

| 端点 | 刻意设置的行为 | |---|---| | GET /users/{id} | 模拟数据库操作：当 id % 10 == 7 时耗时 40 ms，否则耗时 2 ms | | GET /report | 依次执行 3 次数据库调用后，渲染耗时 15 ms | | POST /checkout | 支付调用的超时时限为 30 ms，每 8 个输入中有 1 个会尝试执行耗时 50 ms 的操作 |

这些延迟都是刻意加入的，目的是展示能否通过追踪找出已知原因，并不表明实际数据库存在性能问题。

在记录的这次运行中，287 个请求成功，13 个请求返回状态码 502。追踪器的统计如下：

snippet.txt

started=1100 completed=1100 written=2500
dropped=0 write_errors=0

这 1,100 个跨度包括请求根跨度和子操作。Written 统计的是事件，而非已完成的跨度：1,100 个开始事件、1,100 个结束事件和 300 个属性更新事件，共计 2,500 个事件。

在解读文件之前，请同时检查丢弃数量和写入错误数量。即使查询结果看起来正常，记录也可能并不完整。

查看已完成操作中最慢的那些#

SQLite 接收端提供了 spans_named 视图，其中包含易读的名称和计算好的 duration_ns 列。属性则存储在单独的 attrs 表中。

以只读方式打开已完成记录的文件。

snippet.txt

sqlite3 -readonly traces/your-run.sqlite

首先，按耗时从长到短查看已完成的跨度。

snippet.txt

SELECT
    trace_id,
    id,
    parent_id,
    name,
    ROUND(duration_ns / 1e6, 2) AS duration_ms
FROM spans_named
WHERE end_ns IS NOT NULL
ORDER BY duration_ns DESC
LIMIT 20;

慢请求的根跨度可以帮助确定调查对象。查看其子跨度，就能知道哪些已记录的操作造成了延迟。

将 123 替换为查到的追踪 ID，进一步查看某条追踪。

snippet.txt

SELECT
    id,
    parent_id,
    name,
    ROUND(duration_ns / 1e6, 2) AS duration_ms,
    status,
    error
FROM spans_named
WHERE trace_id = 123
ORDER BY start_ns;

不要把所有行的耗时相加后当作请求耗时。父跨度的时间包含子操作的耗时，而且并发执行的子操作在时间上可能重叠。请结合层级关系和时间戳来解读各个时间区间。

在报表端点中，可以分别看到依次执行的数据库调用和渲染操作。由此便能提出具体的后续问题：“能否合并数据库操作？”“大部分延迟是否来自渲染？”

将慢跨度与输入关联起来#

耗时能帮助确定哪些操作缓慢，属性则能帮助查找触发条件。

以下查询会找出耗时超过 20 毫秒的数据库跨度，并列出记录的 ID。

snippet.txt

SELECT
    t.value AS db_table,
    COUNT(*) AS slow_calls,
    group_concat(i.value, ',') AS ids
FROM spans_named AS s
JOIN attrs AS t
    ON t.span_id = s.id AND t.key = 'db.table'
JOIN attrs AS i
    ON i.span_id = s.id AND i.key = 'db.id'
WHERE s.name = 'db.query'
  AND s.end_ns IS NOT NULL
  AND s.duration_ns > 20e6
GROUP BY t.value;

在这个条件受控的工作负载中，预期会变慢的用户 ID 满足 id % 10 == 7。在实际服务中，同样形式的查询也可能揭示：延迟集中在某类查询或某种输入大小上。

不过，仅凭相关性并不能解释原因。如果怀疑问题出在数据库，请通过查询计划和数据库侧的测量加以确认。

对于失败或未完成的操作，可以使用以下查询。

snippet.txt

SELECT
    CASE
        WHEN end_ns IS NULL THEN 'incomplete'
        WHEN status = 1 THEN 'error'
        ELSE 'canceled'
    END AS outcome,
    name,
    COUNT(*) AS spans,
    MIN(error) AS sample_error
FROM spans_named
WHERE end_ns IS NULL OR status <> 0
GROUP BY outcome, name
ORDER BY spans DESC;

结束时间为 null，意味着结束事件尚未持久化。可能的原因包括：操作尚未完成、事件被丢弃，或进程在刷新前就已退出。

将记录的可靠性也视为结果的一部分#

gospan 通过容量有限的通道，将事件发送给单个负责写入的 goroutine。默认容量为 8,192 个事件。通道满时，默认策略会丢弃新到达的事件，并增加 Stats().Dropped。

也可以改用 WithBlockingPolicy()，等待通道腾出空间。这样可以让事件进入队列，但会给被测操作增加等待时间。

在所提供的高频循环基准测试中，受测配置下的 slog 接收端丢弃了约 80% 的事件。这说明，评估开销时不能忽略数据缺失情况。

SQLite 还存在另一层边界。Written 表示接收端已接受事件，并不保证事件已经保存到持久存储中。接收端会缓冲事件，并在 Flush 时提交。如果刷新失败，待处理的数据会被丢弃，不会重试，失败会计入 WriteErrors。

正常关闭应用很重要。强制终止可能导致队列中的事件或尚未提交的事件丢失。

对于本地调查，只要明确检查这些限制，有时就可以接受。先选一个缓慢的端点，为请求添加跨度，并为开销较大的操作添加包围它们的跨度，然后运行具有代表性的工作负载。确认 Dropped=0 和 WriteErrors=0，查看耗时最长的追踪，再根据其属性选择下一步的测量对象。

来源: https://zenn.dev/nonejp/articles/c7dd2859872f9d

适用于调查范围局限在单个进程内的情况#

创建文件，并在请求入口添加埋点#

为有优化价值的操作添加跨度#

准备一个原因已知的工作负载#

查看已完成操作中最慢的那些#

将慢跨度与输入关联起来#

将记录的可靠性也视为结果的一部分#

加上的角度 0