如何在Kotlin协程中测量异步查询/请求的实际执行时间

现有场景（阻塞JDBC调用）结论 #

你当前使用常规Java JDBC库做阻塞查询，所有查询逻辑包裹在withContext(Dispatchers.IO)块中执行，你之前写的计时方式本身是准确的，不会包含协程挂起时间。
你观测到和串行执行耗时不一致的原因是并发场景下的正常资源竞争，主要包括：

• 数据库连接池的连接数限制，并行请求可能需要等待空闲连接
• 数据库侧CPU、IO、锁资源竞争，并发查询的执行速度本身会慢于串行执行
• 客户端IO线程池的调度开销
  如果需要和协程逻辑完全解耦的精准计时，可以引入JDBC层代理工具统一统计所有SQL的执行耗时。

非阻塞DB驱动场景解决方案 #

如果后续切换到非阻塞DB驱动，查询过程中协程会主动挂起释放线程，此时要排除协程等待调度的时间、只统计查询本身的实际执行时长，可以采用以下两种方案：

方案1：驱动层拦截计时（最准确） #

在DB驱动层做查询拦截，直接统计请求发起到响应返回的时间，完全不受上层协程调度逻辑影响，示例实现如下：

// 非阻塞驱动场景下的查询拦截器示例
class QueryTimeInterceptor : ConnectionPostProcessor {
    override fun postProcess(connection: Connection): Publisher<out Connection> {
        val wrappedConn = ConnectionProxy.builder()
            .delegate(connection)
            .executeListener { context, sql ->
                val startNs = System.nanoTime()
                context.onComplete {
                    val costMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs)
                    logger.info("SQL执行耗时: {}ms, SQL内容: {}", costMs, sql)
                }
            }
            .build()
        return Mono.just(wrappedConn)
    }
}

方案2：协程层CPU时间统计 #

如果需要在业务代码侧统计，可以使用Kotlin协程调试工具包的measureThreadCpuTime方法，直接统计协程实际占用CPU的时长，自动排除挂起等待的时间：

val rawBaseProductsCall = async {
    val execDuration = measureThreadCpuTime {
        productRepository.getBaseProducts(productNos)
    }
    logger.info("rawBaseProductsCall实际执行耗时: ${execDuration.inWholeMilliseconds}ms")
    execDuration.value
}

内容的提问来源于stack exchange，提问作者younes elmorabit