Kotlin嵌套调用measure函数为何耗时差异巨大？求排查方案

先贴出你的代码（修正语法转义问题）：

// added so that it is obvious that this it's not just a delay
inline fun <T> measure(fn: () -> T): T {
    val a = System.currentTimeMillis()
    val r = runCatching { fn() }
    val b = System.currentTimeMillis()
    val seconds = (b - a).toDouble() / 1000.0
    println("Took $seconds to complete")
    return r.getOrThrow()
}

suspend fun doSomething() = ...
suspend fun measureSomething() = measure{
  doSomething()
} // 日志显示耗时7秒

measure{
  measureSomething()
} // 日志显示耗时15秒？这是为什么？

核心原因分析 #

你的measure是非挂起的普通inline函数，但被用来包裹挂起函数调用，这是导致耗时异常的根本问题：

• 内层measure在suspend fun measureSomething()的挂起上下文里执行，调用doSomething()时会正常等待挂起函数完成，因此计时准确（7秒）。
• 外层measure在非挂起上下文调用suspend fun measureSomething()，编译器会强制将挂起函数调用包装成阻塞逻辑（比如隐式依赖runBlocking），额外引入协程启动、线程调度、上下文切换的开销，甚至可能因为线程池资源不足导致等待，最终总耗时大幅增加。

具体排查步骤 #

1. 修正测量函数为挂起版本
   把measure改成支持挂起lambda的版本，确保能覆盖挂起函数的完整执行周期：

   suspend inline fun <T> measureSuspend(fn: suspend () -> T): T {
       val a = System.currentTimeMillis()
       val r = runCatching { fn() }
       val b = System.currentTimeMillis()
       val seconds = (b - a).toDouble() / 1000.0
       println("Took $seconds to complete")
       return r.getOrThrow()
   }
   

   替换所有调用后，观察耗时差异是否消失。

2. 检查线程与调度器
   在关键位置打印当前线程信息，确认内外层调用的执行上下文：

   // 在measure函数开头添加
   println("Measure running on: ${Thread.currentThread().name}")
   // 在doSomething开头添加
   println("DoSomething running on: ${Thread.currentThread().name}")
   

   如果内外层使用不同的调度器（比如内层用IO、外层用Default），上下文切换的开销可能被放大。

3. 验证业务逻辑稳定性
   单独多次调用doSomething()，记录每次耗时，排除业务逻辑本身的波动（比如依赖的外部服务响应不稳定）。

4. 排查阻塞操作
   检查doSomething()是否使用了阻塞式API（比如Thread.sleep、同步JDBC），而非协程友好的挂起API（比如delay、suspendCoroutine包装的IO）。阻塞操作会占用协程调度器线程，导致后续请求排队，放大耗时。

5. 测试inline的影响
   临时移除measure函数的inline修饰符，观察耗时变化，排查inline特性导致的协程上下文捕获异常。

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