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

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.

CodePudding user response：

I don't do Kotlin my self so I cannot give a code sample.

But in theory you know when you raise a request, so remember that timestamp in a variable next to the request (id, token, ...). As soon as the response becomes available (however you get to know about it) store the second timestamp, then print the difference which is the elapsed time.

I doubt you will get any closer to that.

CodePudding user response：

I don't know if this is intentional or by a mistake, but you use only a single thread here. You start tens or even hundreds of coroutines and they all fight each other for this single thread. If you perform any CPU-intensive processing in "here I wait for all the results and then some processing on thm" then while it is working, all other coroutines have to wait to be resumed from withContext(Dispatchers.IO). If you want to utilize multiple threads, replace runBlocking {} with runBlocking(Dispatchers.Default) {}.

Still, it doesn't fix the problem, but rather lessens its impact. Regarding the proper fix: if you need to measure the time spent in the IO only then... measure the time in the IO only. Just move your measurements inside withContext(Dispatchers.IO) and I think results will be closer to what you expect. Otherwise, it is like measuring the size of a room by standing outside the building.