How to measure execution time of an aync query/request inside Kotlin coroutines

I have a microservice on which I am using Kotlin coroutines to perform a bunch of db queries asynchronously, and I want to monitor the execution time for each one of those queries for potential performance optimization.

The implementation I have is like this:

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()
}

As you can see I use Semaphore to limit the number of parallel jobs, and all the repository methods are suspendable and those are the ones I want to measure the execution time for. Here is an example of an implementation inside ProductRepository:

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

And to do that I tried this :

      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
      }

But this measurement always returns inconsistent results for the average in contrast to the sequential implementation(without coroutines), and the only explanation I can come up with is that this measurement includes the suspension time, and obviously I am only interested in the time that the queries take to execute without a suspension time if there was any.

I don’t know if what I am trying to do is possible in Kotlin, but it looks like python supports this. So I will appreciate any help to do something similar in Kotlin.

UPDATE:

In my case I am using a regular java library to query the db, so my DB queries are just regular blocking calls which means that the way I am measuring time right now is correct.

The assumption I made in the question would have been valid if I was using some implementation of R2DBC for querying my DB.

Answer

you do not want to measure the coroutine startup or suspension time so you need to measure over a block of code that will not suspend, ie.. your database calls from a java library

stdlib for example provides a few nice functions like measureTimedValue

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

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

Advertisement

Answer