Reactive request is not properly propagated as cursor batch size

[kschlesselmann]

Since the upgrade to Spring Boot 3.1 we noticed a major performance degradation in comparison to our previous Spring Boot 2.7 environment. Now it looks like that the cursor batch size for mongo queries has changed. The old 2.7 service seems to use a default of 32 (24 getMore). The new 3.1 service seems to be using a cursor size of 2.

To reproduce run this litte snippet either with SB 2.7 or SB 3.1

@Document
data class Thing(val name: String, @Id val id: UUID = UUID.randomUUID())

interface ThingRepository : ReactiveCrudRepository<Thing, UUID>

@SpringBootApplication
class Demo1Application {

    @Bean
    fun test(thingRepository: ThingRepository) = ApplicationRunner {
        Flux.range(0, 1) // increase this to generate more samples
            .map { Thing(name = "Oimel $it") }
            .collectList()
            .flatMapMany { thingRepository.saveAll(it) }
            .flatMap {
                thingRepository.findAll()
                    .doOnRequest { println("Requested $it") }
                    //.flatMap({ Mono.just(it) }, 8) // use this to request multiple small batches
                    .collectList()
            }
            .blockLast()
    }
}

fun main(args: Array<String>) {
    runApplication<Demo1Application>(*args)
}

Running this with SB 3.1 results in the following log (with logging.level: org.mongodb: debug)

...

Requested 9223372036854775807
2023-11-02T15:20:11.202+01:00 DEBUG 913 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "find" started on database test using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 6. Command: {"find": "thing", "filter": {}, "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "vTi0GdDgQACDenLxyS0dqQ==", "subType": "04"}}}}
2023-11-02T15:20:11.204+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "find" succeeded in 2,12 ms using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 6. Command reply: {"cursor": {"firstBatch": [{"_id": {"$binary": {"base64": "wU6wcB3AUdk171ISY6wilA==", "subType": "03"}}, "name": "Oimel 5", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "JERXcnYlt6cdtn7GHVCEnQ==", "subType": "03"}}, "name": "Oimel 13", "_class": "com.example.demo.Thing"}], "id": 1440510796141382911, "ns": "test.thing"}, "ok": 1.0}
2023-11-02T15:20:11.206+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 1440510796141382911 from server localhost:27017
2023-11-02T15:20:11.212+01:00 DEBUG 913 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 7. Command: {"getMore": 1440510796141382911, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "vTi0GdDgQACDenLxyS0dqQ==", "subType": "04"}}}}
2023-11-02T15:20:11.213+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 1,51 ms using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 7. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "UUDQKQ+rQ6LcEK26ymaatg==", "subType": "03"}}, "name": "Oimel 15", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "3UW8nReu/bwP+xR+2PMQtA==", "subType": "03"}}, "name": "Oimel 16", "_class": "com.example.demo.Thing"}], "id": 1440510796141382911, "ns": "test.thing"}, "ok": 1.0}
2023-11-02T15:20:11.214+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 1440510796141382911 from server localhost:27017
2023-11-02T15:20:11.214+01:00 DEBUG 913 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 8. Command: {"getMore": 1440510796141382911, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "vTi0GdDgQACDenLxyS0dqQ==", "subType": "04"}}}}
2023-11-02T15:20:11.216+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 0,98 ms using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 8. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "uUNBCdBVkj1InxjNI4bWkw==", "subType": "03"}}, "name": "Oimel 18", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "rU6tQQIjfM7StaHMvAgXjQ==", "subType": "03"}}, "name": "Oimel 17", "_class": "com.example.demo.Thing"}], "id": 1440510796141382911, "ns": "test.thing"}, "ok": 1.0}
2023-11-02T15:20:11.216+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 1440510796141382911 from server localhost:27017
2023-11-02T15:20:11.216+01:00 DEBUG 913 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 9. Command: {"getMore": 1440510796141382911, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "vTi0GdDgQACDenLxyS0dqQ==", "subType": "04"}}}}
2023-11-02T15:20:11.217+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 0,72 ms using a connection with driver-generated ID 3 and server-generated ID 152 to localhost:27017. The request ID is 9. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "sE7piYIJMnvaI2qPymxWvA==", "subType": "03"}}, "name": "Oimel 20", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "bEJTuvnZT13LQ4lQA+BGtQ==", "subType": "03"}}, "name": "Oimel 19", "_class": "com.example.demo.Thing"}], "id": 1440510796141382911, "ns": "test.thing"}, "ok": 1.0}
2023-11-02T15:20:11.218+01:00 DEBUG 913 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 1440510796141382911 from server localhost:27017

... and so on ...

I don't think this is working as intended, is it?

[mp911de]

Project Reactor revised prefetch sizes by quite a bit (e.g. concatMap changed from 8 to zero, reactor/reactor-core#2967). I think something similar is going on here with flatMap. I highly suggest setting the fetch size for cursored operations or using limitRate as the first operator after findAll to shape the request size.

[kschlesselmann]

@mp911de But that's why I logged the request to findAll() (9223372036854775807). Even if I change to code to

thingRepository.findAll()
    .doOnRequest { println("Requested $it") }
    .limitRate(10)
    .collectList()

I still end up with

Requested 10
2023-11-03T12:41:18.022+01:00 DEBUG 29054 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "find" started on database test using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 6. Command: {"find": "thing", "filter": {}, "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "AgcymOq5Qj+dJH2+wDtkWQ==", "subType": "04"}}}}
2023-11-03T12:41:18.025+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "find" succeeded in 2,81 ms using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 6. Command reply: {"cursor": {"firstBatch": [{"_id": {"$binary": {"base64": "50WyFWKjoX9ddsdLpuYEqw==", "subType": "03"}}, "name": "Oimel 5", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "IE8A5L2ImEC7jPWXxYHskA==", "subType": "03"}}, "name": "Oimel 15", "_class": "com.example.demo.Thing"}], "id": 2129980180013329418, "ns": "test.thing"}, "ok": 1.0}
2023-11-03T12:41:18.026+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 2129980180013329418 from server localhost:27017
2023-11-03T12:41:18.035+01:00 DEBUG 29054 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 7. Command: {"getMore": 2129980180013329418, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "AgcymOq5Qj+dJH2+wDtkWQ==", "subType": "04"}}}}
2023-11-03T12:41:18.037+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 1,75 ms using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 7. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "hEXFvyeJ4lxXY3pzk7Dukw==", "subType": "03"}}, "name": "Oimel 66", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "WUKRspJ/ZTPpzznU40F6kQ==", "subType": "03"}}, "name": "Oimel 17", "_class": "com.example.demo.Thing"}], "id": 2129980180013329418, "ns": "test.thing"}, "ok": 1.0}
2023-11-03T12:41:18.037+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 2129980180013329418 from server localhost:27017
2023-11-03T12:41:18.038+01:00 DEBUG 29054 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 8. Command: {"getMore": 2129980180013329418, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "AgcymOq5Qj+dJH2+wDtkWQ==", "subType": "04"}}}}
2023-11-03T12:41:18.039+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 1,46 ms using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 8. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "xUvsHp5YsZgVkf7xhn43pg==", "subType": "03"}}, "name": "Oimel 16", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "OUBK5FJoJrr1P/6AYgrjtw==", "subType": "03"}}, "name": "Oimel 19", "_class": "com.example.demo.Thing"}], "id": 2129980180013329418, "ns": "test.thing"}, "ok": 1.0}
2023-11-03T12:41:18.040+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 2129980180013329418 from server localhost:27017
2023-11-03T12:41:18.040+01:00 DEBUG 29054 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 9. Command: {"getMore": 2129980180013329418, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "AgcymOq5Qj+dJH2+wDtkWQ==", "subType": "04"}}}}
2023-11-03T12:41:18.041+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 1,08 ms using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 9. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "90xQwDgojw3Qxw3E8CZMkw==", "subType": "03"}}, "name": "Oimel 18", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "10X4yS9weXg7lZKNnDNyoQ==", "subType": "03"}}, "name": "Oimel 20", "_class": "com.example.demo.Thing"}], "id": 2129980180013329418, "ns": "test.thing"}, "ok": 1.0}
2023-11-03T12:41:18.042+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 2129980180013329418 from server localhost:27017
Requested 8
2023-11-03T12:41:18.042+01:00 DEBUG 29054 --- [tter-2-thread-1] org.mongodb.driver.protocol.command      : Command "getMore" started on database test using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 10. Command: {"getMore": 2129980180013329418, "collection": "thing", "batchSize": 2, "$db": "test", "lsid": {"id": {"$binary": {"base64": "AgcymOq5Qj+dJH2+wDtkWQ==", "subType": "04"}}}}
2023-11-03T12:41:18.043+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.protocol.command      : Command "getMore" succeeded in 0,76 ms using a connection with driver-generated ID 3 and server-generated ID 107 to localhost:27017. The request ID is 10. Command reply: {"cursor": {"nextBatch": [{"_id": {"$binary": {"base64": "zENpMCTsV0UgXVwe5jkgsA==", "subType": "03"}}, "name": "Oimel 21", "_class": "com.example.demo.Thing"}, {"_id": {"$binary": {"base64": "EUtQXJIaddDLpH2B9VnZgQ==", "subType": "03"}}, "name": "Oimel 23", "_class": "com.example.demo.Thing"}], "id": 2129980180013329418, "ns": "test.thing"}, "ok": 1.0}
2023-11-03T12:41:18.043+01:00 DEBUG 29054 --- [ntLoopGroup-3-3] org.mongodb.driver.operation             : Received batch of 2 documents with cursorId 2129980180013329418 from server localhost:27017

...

[mp911de]

FluxConcatMapNoPrefetch translates request(100) to upstream.request(1). Switching from concatMap to flatMapSequential restores the prefetch behavior (Received batch of 100 documents with cursorId 0 from server 127.0.0.1:27017). Paging @christophstrobl @pderop

Switching from concatMap to flatMapSequential will open up the possibility of concurrent failures, but as that has already been possible with previous versions, I don't see that we would introduce a regression.

[kwazii1231]

@christophstrobl
thanks for fix this issue.
i also found same issues during my works
and now i'm understood what's going on.
so which version should i use to fix this issue?
milestone marked as 4.0.12 but it is previous version and i'm already use 4.1.5 of spring-data-mongodb
so little bit confused.
please let't me know which version should i have to pick after your release!
thanks!

[christophstrobl]

@kwazii1231 GH only allows to assign a single milestone. So we pick the 'oldest' version that contains the fix and every version after that (from a date perspective) will also contain it. In this case it will be 4.12.0, 4.1.6 and 4.2.0.