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 数量多、标签基数高都会影响性能。埋点也要做性能评估——这是一个有趣的自指问题。