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

Question

我有一个微服务，我正在使用 Kotlin 协程异步执行一堆 db 查询，我想监控每个查询的执行时间，以实现潜在的性能优化。

我的实现是这样的：

val requestSemaphore = Semaphore(5)
val baseProductsNos = productRepository.getAllBaseProductsNos()
runBlocking {
    baseProductsNos
        .chunked(500)
        .map { batchOfProductNos ->
            launch {
                requestSemaphore.withPermit {
                    val rawBaseProducts = async {
                        productRepository.getBaseProducts(batchOfProductNos)
                    }

                    val mediaCall = async {
                        productRepository.getProductMedia(batchOfProductNos)
                    }

                    val productDimensions = async {
                        productRepository.getProductDimensions(batchOfProductNos)
                    }

                    val allowedCountries = async {
                        productRepository.getProductNosInCountries(batchOfProductNos, countriesList)
                    }

                    val variants = async {
                        productRepository.getProductVariants(batchOfProductNos)
                    }

                    // here I wait for all the results and then some processing on thm
                }
            }
        }.joinAll()
}

如您所见，我使用 Semaphore 来限制并行作业的数量，并且所有存储库方法都是可挂起的，而这些是我想要测量其执行时间的方法。下面是 ProductRepository 中的一个实现示例：

  suspend fun getBaseProducts(baseProductNos: List<String>): List<RawBaseProduct> =
    withContext(Dispatchers.IO) {
      namedParameterJdbcTemplateMercator.query(
        getSqlFromResource(baseProductSql),
        getNamedParametersForBaseProductNos(baseProductNos),
        RawBaseProductRowMapper()
      )
    }

为此，我尝试了这个：

      val rawBaseProductsCall = async {
        val startTime = System.currentTimeMillis()

        val result = productRepository.getBaseProducts(productNos)

        val endTime = System.currentTimeMillis()
        logger.info("${TemporaryLog("call-duration", "rawBaseProductsCall", endTime - startTime)}")

        result
      }

但是与顺序实现（没有协程）相比，这个测量总是返回不一致的平均值结果，我能想出的唯一解释是这个测量包括暂停时间，显然我只对查询在没有暂停时间的情况下执行所花费的时间（如果有的话）。

我不知道在 Kotlin 中我想要做的事情是否可行，但看起来 python 支持这一点。因此，我将不胜感激在 Kotlin 中做类似事情的任何帮助。

更新：

在我的例子中，我使用常规的 java 库来查询数据库，所以我的数据库查询只是常规的阻塞调用，这意味着我现在测量时间的方式是正确的。

如果我使用R2DBC 的某些实现来查询我的数据库，我在问题中所做的假设将是有效的。

Answer 1

您不想测量协程启动或挂起时间，因此您需要测量不会挂起的代码块，即...您的数据库调用来自 java 库

例如，stdlib 提供了一些不错的函数，例如 measureTimedValue

val (duration, result) = measureTimedValue {
    doWork()
    // eg: productRepository.getBaseProducts(batchOfProductNos)
}
logger.info("operation took $duration")

https://kotlinlang.org/api/latest/jvm/stdlib/kotlin.time/measure-timed-value.html

Answer 2

我自己不做 Kotlin，所以我不能给出代码示例。

但理论上您知道何时提出请求，因此请记住请求旁边变量中的时间戳（id、token、...）。一旦响应变得可用（无论您如何了解它），就存储第二个时间戳，然后打印经过时间的差异。

我怀疑你会更接近那个。

Answer 3

我不知道这是故意的还是错误的，但你在这里只使用了一个线程。您启动了数十甚至数百个协程，它们都为这个单一线程而战。如果您在“我在这里等待所有结果，然后在 thm 上进行一些处理”中执行任何 CPU 密集型处理，那么当它工作时，所有其他协程必须等待从 withContext(Dispatchers.IO) 恢复。如果要使用多线程，请将runBlocking {} 替换为runBlocking(Dispatchers.Default) {}。

不过，它并没有解决问题，而是减轻了它的影响。关于正确的修复：如果您只需要测量在 IO 中花费的时间，那么......仅在 IO 中测量时间。只需将您的测量结果移到withContext(Dispatchers.IO) 内，我认为结果会更接近您的预期。否则，这就像站在建筑物外面测量房间的大小。