KMongo and coroutines

Question

I have a question related to coroutines and KMongo. I'm using KMongo CoroutineCollection to find some records in the database. On my local computer it takes <0.5sec but when I do the same thing on development environment it takes 10-25 seconds.

The app runs on Spring Boot Netty server with reactor to support coroutines. I'm using also DGS to set up GraphQL endpoints. The simplified callstack is:

DGSQuery suspend fun -> suspend fun |
                                    | -> suspend fun KMongo first CoroutineCollection.find()
                                    | -> suspend fun KMongo second CoroutineCollection.find()

It seems the default batchSize is 2, so I can see multiple queries run under the hood. My suspicion is that the code operates on 1 thread that is used across the app and that's why it takes much longer on dev vs local (less clients and scheduled operations). This is how logs look like:

[ctor-http-nio-1][][] c.x.d.a.wellreport.***Resolver           : wellReports run
[ctor-http-nio-1][][] c.x.d.d.wellreport.***Service            : all***Provider.invoke() start
[ctor-http-nio-1][][] d.m.w.Mongo***Repository                 : fetchAll started
[tter-2-thread-1][][] org.mongodb.driver.protocol.command      : Sending command '{"find": "***", "filter": {}, "batchSize": 100, "$db": "***", "lsid": {"id": {"$binary": {"base64": "hdGYjs3YSX6K5y2YJzUJkw==", "subType": "04"}}}}' with request id 56 to database *** on connection [connectionId{localValue:22, serverValue:1902}] to server localhost:27017
[ntLoopGroup-3-6][][] org.mongodb.driver.protocol.command      : Execution of command with request id 56 completed successfully in 13.32 ms on connection [connectionId{localValue:22, serverValue:1902}] to server localhost:27017
[ntLoopGroup-3-6][][] org.mongodb.driver.operation             : Received batch of 54 documents with cursorId 0 from server localhost:27017
[ntLoopGroup-3-6][][] d.m.w.Mongo***Repository                 : fetchAll finished
[ntLoopGroup-3-6][][] c.x.d.d.wellreport.***Service            : all***Provider.invoke() finished
[ntLoopGroup-3-6][][] c.x.d.d.wellreport.***Service            : positive***Provider.invoke() start
[ntLoopGroup-3-6][][] w.Mongo***Repository                     : fetchAllPositive start
[tter-2-thread-1][][] org.mongodb.driver.protocol.command      : Sending command '{"find": "***", "filter": {"score": {"$gt": 0.0}}, "batchSize": 2, "$db": "***", "lsid": {"id": {"$binary": {"base64": "hdGYjs3YSX6K5y2YJzUJkw==", "subType": "04"}}}}' with request id 57 to database *** on connection [connectionId{localValue:22, serverValue:1902}] to server localhost:27017
[ntLoopGroup-3-6][][] org.mongodb.driver.protocol.command      : Execution of command with request id 57 completed successfully in 5.26 ms on connection [connectionId{localValue:22, serverValue:1902}] to server localhost:27017
[ntLoopGroup-3-6][][] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 6831622277590159417 from server localhost:27017

This is how repository class look like:

class MongoXXXScoreRepository(private val collection: CoroutineCollection<MongoXXXScore>) : XXXScoreRepository {
    private val logger by logger()
    override suspend fun fetchAllPositive(): List<XXXScore> {
        logger.info("fetchAllPositive start")
        val result = collection.find(MongoXXXScore::score gt 0.0).toList().map { it.toXXXScore() }
        logger.info("fetchAllPositive start")
        return result
    }
}

Interesting part to me is that after calling the first KMongo .find() the thread changes to a different one and continues on that thread till the end. This doesn't sound right to me. Any thoughts?

Answer 1

It seems the default batchSize is 2, so I can see multiple queries run under the hood. My suspicion is that the code operates on 1 thread that is used across the app and that's why it takes much longer on dev vs local

I think multiple round-trip costs is a more likely explanation. If you have n documents, the time taken is n/2*rtt.

I don't think it's a stretch to imagine your dev environment has a round trip time 20x your local machine.

So an easy fix is to simply increase your batchSize.

the thread changes to a different one and continues on that thread till the end.

This is less surprsing when you remember coroutines are pretty much callbacks. Dispatchers.Default, for example, has a thread pool to schedule multiple coroutines. This is called M:N threading.