文档目录

1.3 配套代码:三个测量点的埋点与延迟分解

对应小节:1.3 测量点 目标:让代码能回答「这个接口的 P99 里,数据库占多少毫秒、排队占多少毫秒、我写的代码占多少毫秒」。

一、依赖级计时器

// src/main/kotlin/metrics/TimedDependency.kt
package metrics

import io.micrometer.core.instrument.MeterRegistry
import io.micrometer.core.instrument.Timer
import java.time.Duration

/**
 * 每个依赖一个 Timer。
 * 注意:这里用 builder 而不是 record(),因为需要为每个依赖单独配置桶边界。
 */
class DependencyTimers(registry: MeterRegistry) {

    private fun timer(name: String, description: String): Timer =
        Timer.builder(name)
            .description(description)
            .publishPercentileHistogram(true)
            .serviceLevelObjectives(*sloBuckets.toTypedArray())
            .minimumExpectedValue(Duration.ofMillis(1))
            .maximumExpectedValue(Duration.ofSeconds(5))
            .register(registry)

    val postgres = timer("dep.postgres", "PostgreSQL 调用耗时(含等待连接)")
    val redis = timer("dep.redis", "Redis 调用耗时")
    val downstream = timer("dep.downstream", "下游 HTTP 调用耗时")

    /**
     * 跨越挂起点的计时是合法的:Timer.Sample 只记录起始时刻。
     * 因此协程调度的时间也会被计入 —— 这正是我们想要的(用户看到的就是这段时间)。
     */
    suspend fun <T> timed(timer: Timer, registry: MeterRegistry, block: suspend () -> T): T {
        val sample = Timer.start(registry)
        return try {
            block()
        } finally {
            sample.stop(timer)
        }
    }
}

一个容易忽略的细节:dep.postgres 的计时包含了「等连接池分配连接」的时间。这其实很有用——如果这个 Timer 的 P99 突然飙升,你要进一步区分「等连接」和「查询慢」,方法是同时看 db_pool_pending 指标(饱和度层)。

二、三个测量点的完整埋点

// src/main/kotlin/Routes.kt
package app

import io.ktor.http.*
import io.ktor.server.application.*
import io.ktor.server.response.*
import io.ktor.server.routing.*
import io.micrometer.core.instrument.MeterRegistry
import io.micrometer.core.instrument.Timer
import io.micrometer.core.instrument.distribution.DistributionStatisticConfig
import metrics.DependencyTimers
import java.time.Duration

fun Application.orderRoutes(
    registry: MeterRegistry,
    deps: DependencyTimers,
    repo: OrderRepository,
    cache: OrderCache,
) {
    // ── 测量点 ③:应用内 —— handler 级别(这是"应用自身处理时间") ──
    val handlerTimer = Timer.builder("app.handler.duration")
        .description("handler 内部耗时(不含网络与网关)")
        .publishPercentileHistogram(true)
        .serviceLevelObjectives(*metrics.sloBuckets.toTypedArray())
        .register(registry)

    routing {
        get("/orders/{id}") {
            val id = call.parameters["id"]!!
            val sample = Timer.start(registry)          // ← 从进入 handler 开始计时

            try {
                // 依赖 1:缓存(可能命中,可能未命中)
                val cached = deps.timed(deps.redis, registry) { cache.get(id) }

                val order = cached ?: deps.timed(deps.postgres, registry) {
                    // 注意:这个 Timer 覆盖了「等连接 + 执行 SQL + 映射结果」
                    repo.findById(id)
                }

                // 依赖 2:下游服务(并行调用时要用 async)
                val user = deps.timed(deps.downstream, registry) {
                    userClient.fetch(order.userId)
                }

                call.respond(order.copy(userName = user.name))
            } finally {
                sample.stop(handlerTimer)               // ← 到响应返回为止
            }
        }
    }
}

这一段代码给了你三个数字:

指标 含义
app.handler.duration 应用内耗时(测量点 ③)
dep.postgres / dep.redis / dep.downstream 每个依赖的耗时
http_server_requests(由 Ktor 插件自动埋) 服务端观测的完整耗时(测量点 ② 近似)

再加上压测客户端的数字(测量点 ①),就能做完整的差额分析。

三、把差额做出来:三条 PromQL

① 应用自身开销 = handler 延迟 − 各依赖延迟之和

# 应用自身开销(序列化、业务计算、锁等)
histogram_quantile(0.99,
  sum by (le) (rate(app_handler_duration_seconds_bucket[5m])))
-
(
  histogram_quantile(0.99, sum by (le) (rate(dep_postgres_seconds_bucket[5m])))
  +
  histogram_quantile(0.99, sum by (le) (rate(dep_redis_seconds_bucket[5m])))
  +
  histogram_quantile(0.99, sum by (le) (rate(dep_downstream_seconds_bucket[5m])))
)

警告:这个减法只在串行调用时成立。并行调用时要取 max 而不是 sum(见下方「局限」)。

② 服务排队 = 服务端观测延迟 − 应用内延迟

histogram_quantile(0.99,
  sum by (le) (rate(http_server_requests_seconds_bucket{uri="/orders/{id}"}[5m])))
-
histogram_quantile(0.99,
  sum by (le) (rate(app_handler_duration_seconds_bucket[5m])))

这一项如果很大,说明请求在排队等着被处理(等线程、等 CPU、等协程调度)。这部分延迟不在任何代码里,只能靠这个差额 + 饱和度指标发现。

③ 网络 + 客户端排队 = 客户端延迟 − 服务端延迟

这一项无法用 PromQL 算(客户端数据不在 Prometheus 里),要在压测报告里手动对比。

四、把三个测量点画成一张对照表

跑完压测后,把三处的数据填进这张表——这就是你的延迟分解结果:

测量点 P50 P95 P99
① 客户端(k6 报告)
② 服务端(http_server_requests)
③ 应用内(app_handler_duration)
└ dep.postgres
└ dep.redis
└ dep.downstream
应用自身开销(③ − 依赖之和)
服务排队(② − ③)
网络 + 客户端排队(① − ②)

判读规则:

现象 结论 下一步
① − ② 很大 网络或压测客户端有问题 查压测机资源、网络、是否同机
② − ③ 很大 服务在排队 查线程池队列、CPU 节流、协程调度器
③ − 依赖之和 很大 你自己的代码慢 采火焰图(第 6 章)
某个 dep.* 很大 该依赖是瓶颈 查数据库/缓存/下游

五、四个必须避免的埋点错误

// ❌ 错误 1:分母只算成功请求 → 超时的慢请求被剔除
if (success) timer.record(duration)

// ✅ 正确:无论成败都记录
try { ... } finally { sample.stop(timer) }

// ❌ 错误 2:计时范围漏掉序列化
sample.stop(timer)          // 在 respond 之前就停止了
call.respond(order)         // 序列化发生在这里,没被计入

// ✅ 正确:把 respond 包在计时范围内(或用 Ktor 插件的全量计时)

// ❌ 错误 3:用 requestId / userId 当标签 → 指标基数爆炸
registry.counter("req", "id", requestId)

// ✅ 正确:只用可枚举维度
registry.counter("req", "uri", "/orders/{id}", "status", "200")

// ❌ 错误 4:Timer 名字里带动态值
Timer.builder("req.$uri")   // 每个 URL 一个 Timer

// ✅ 正确:固定名字 + 标签
Timer.builder("req").tag("uri", routeTemplate)

六、这段代码的局限

  • 并行调用的减法不成立。如果 Redis 和 PostgreSQL 是并发调用的,总耗时是 max(25, 3) = 25 而不是 28。此时「handler − 依赖之和」会低估自身开销,甚至算出负数。并行链路的正确做法是用 tracing 的 span 树看关键路径(第 4 章)。
  • dep.* 的计时包含了「等连接池」的时间。要区分「等连接」和「查询慢」,需同时看 db_pool_pending。
  • 异步/协程场景下,计时跨越挂起点会把调度时间也算进去。多数时候这是对的(那就是用户等待的时间),但如果你要区分「CPU 时间」和「等待时间」,需要用别的手段(火焰图)。
  • 指标本身有成本:Timer 数量多、标签基数高都会影响性能。埋点也要做性能评估——这是一个有趣的自指问题。