Spring Spring generates huge callstack for async requests

Affects: 5.2.4.RELEASE

For coroutines response, Spring generates a lot of intermediate classes and produce deep callstack.

Question: is it bug or feature?

Potentially this can lead to increased memory traffic and performance degradation.

Possible fix - use kotlin inside the spring (which produce smaller callstack, because of set of optimizations) or return initial mono if no additional actions is needed (e.g. try avoid creation new Mono object if possible)

Callstack example:

    at org.springframework.web.reactive.function.server.CoRouterFunctionDsl$asHandlerFunction$1$1.invokeSuspend(CoRouterFunctionDsl.kt:599)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedContinuationKt.resumeCancellableWith(DispatchedContinuation.kt:313)
    at kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:26)
    at kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:109)
    at kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:158)
    at kotlinx.coroutines.reactor.MonoKt$monoInternal$1.accept(Mono.kt:55)
    at kotlinx.coroutines.reactor.MonoKt$monoInternal$1.accept(Mono.kt)
    at reactor.core.publisher.MonoCreate.subscribe(MonoCreate.java:57)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:76)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:274)
    at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:851)
    at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:114)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:114)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2267)
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2075)
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:1949)
    at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:78)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
    at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136)
    at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136)
    at reactor.core.publisher.Operators.complete(Operators.java:135)
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:441)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:211)
    at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:161)
    at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4110)
    at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:172)
    at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55)
    at reactor.netty.http.server.HttpServerHandle.onStateChange(HttpServerHandle.java:64)
    at reactor.netty.tcp.TcpServerBind$ChildObserver.onStateChange(TcpServerBind.java:228)
    at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:465)
    at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:90)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:170)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:321)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:295)
    at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792)
    at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$1.run(AbstractEpollChannel.java:387)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)

Comment From: rstoyanchev

This seems to be handling a server request based on HttpServerHandle.java:64 and then there is a lot of repeated subscriptions to Mono.empty driven with FluxSwitchIfEmpty. Just a guess that this may be as a result of a functional route evaluation. Can you share a little more about the source code for this?

Comment From: imanushin

I register all handlers via the following code:

private fun CoRouterFunctionDsl.addGetHandler(
    suffix: UrlSuffix,
    processingMethod: suspend (ServerRequest) -> ServerResponse // Spring classes
) {
    GET("/$suffix", processingMethod)
}

The processingMethod is suspend function, so everything under it knows nothing about Mono class.

The simplified version of global registration handler is:

@Bean
open fun httpEndpoints() = coRouter {
    htmlGenerators.generators.forEach { // 
        addGetHandler(it.url, it.method) // this function is described above
    }
}

The simplified implementation of the one handler is:

suspend fun process(request: ServerRequest): ServerResponse {
    return try {
        val result = computeResult() // kotlin suspend method
        ServerResponse.ok()
            .bodyValueAndAwait(result)
    } catch (e: Exception) {
        ServerResponse.status(HttpStatus.INTERNAL_SERVER_ERROR)
            .bodyValueAndAwait(e.message ?: "")
    }
}

Comment From: rstoyanchev

Okay so just a series of route declarations.

I believe this is due to the way functional routes work. After the first route is evaluated, if it doesn't match, the switchIfEmpty operator invokes the second, and so on. This nesting is expected in a functional route chain. The reactive contract for RouterFunction does require an additional switchIfEmpty operator and Mono.defer for each route (and that enables non-blocking behavior in route functions and filters) but the basic principle remains that the longer the chain, and the longer the request doesn't match, the deeper the stack. @poutsma please correct me if I'm wrong.

You may be able to make the evaluation more optimal by ordering most common routes first, and/or using nested routes to split routes into smaller groups at the top, e.g. by using high-level patterns, and HTTP methods, in order to reduce the number of steps.

That said there may also be room for optimization. For example this Mono.just maybe doesn't need to be re-created every time. Probably worth a review with an eye towards possible optimizations.

Comment From: poutsma

@rstoyanchev You are correct.

Comment From: rstoyanchev

@imanushin thanks for the code snippets above. We'd like to get a better sense of the URL space and routing rules you have, so we can suggest ways to split and divide through nested routes.

Generally there is some guidance to come out of this, and become a documentation improvement, about how to think about organizing routes optimally, and there is also a lot of flexibility since you can create your own routes, but it would be useful first to better understand your case better.

Comment From: imanushin

@rstoyanchev , please check the code below. As you can see, I have only few endpoints (~25 totally). And all of them are static, without any templates.

I thank that this configuration can be processed with O(N), where N is min(sizeOfRequestUrl, sizeOfMatchedUrl), e.g. I thank that solver worked with Trie algorithm inside.

@Bean
open fun httpEndpoints(
    htmlGenerators: HtmlGenerators
) = coRouter {
    val htmlHandlers = htmlGenerators.generators /*size - about 20 items*/

    indexPageService.synonyms.forEach { url -> // ~5 synonyms for index page
        GET(url) {
            val html = indexPageService.getHtmlPageContent()

            ServerResponse
                .ok()
                .contentType(MediaType.TEXT_HTML)
                .bodyValueAndAwait(html)
        }
    }

    endpoints.forEach { (/*each suffix is /commonPrefix/[enumValue]*/ suffix: String, handler) ->
            GET(suffix) { request ->
                handler.process(request)
            }
    }
}

Comment From: rstoyanchev

This doesn't make clear for me I'm afraid. Seeing concrete mappings (real or sample) rather than code would probably be more helpful.

Normally URLs with a common prefix are processed with as one pattern with a template variable.

Comment From: imanushin

@rstoyanchev, I wrote small sample application, which reproduces the issue - https://github.com/imanushin/spring-flux-callstack

It has the following routes: /g/1, /g/2, /g/3, ..., /g/999

Comment From: rstoyanchev

Thanks @imanushin. I wasn't disputing what happens if you have a 1000 patterns. I wanted to understand your pattern space to reason specifically about how to lay it out other than sequentially.

For example for 20 resources with a common prefix, I might see one pattern only:

RouterFunctions.route()
        .GET("/commonPrefix/{*subpath}", request -> {
                String subPath = request.pathVariable("subpath");
                Resource resource = ... ;
                return ServerResponse.ok().body(BodyInserters.fromResource(resource));
         });

There may be other ways to split the mappings with nest routing.

If you have a 1000 paths to check you could write:

Map<String, HandlerFunction<ServerResponse>> mappings = new HashMap<>();
for (int i = 0; i < 1000; i++) {
    mappings.put("/g/" + i, request -> ServerResponse.ok().build());
}

RouterFunctions.route()
    .add(request ->
        mappings.entrySet().stream()
            .filter(e -> e.getKey().matches(request.path()))
            .findFirst()
            .map(e -> Mono.just(e.getValue()))
            .orElse(Mono.empty()));

Or with patterns:

PathPatternParser patternParser = new PathPatternParser();

Map<PathPattern, HandlerFunction<ServerResponse>> map = new HashMap<>();
for (int i = 0; i < 1000; i++) {
    map.put(patternParser.parse("/g/" + i), request -> ServerResponse.ok().build());
}

RouterFunctions.route()
    .add(request ->
        map.entrySet().stream()
            .filter(e -> e.getKey().matches(request.pathContainer()))
            .findFirst()
            .map(e -> Mono.just(e.getValue()))
            .orElse(Mono.empty()));

Comment From: poutsma

Another think to consider, if the handler method is (or can be made) generic, is to compose multiple request predicates into one using or, like shown here. So rather that having 1000 routes, you would have 1 route with 1000 predicates, all OR-combined. Composing request predicates this way is always going to be quicker than having multiple routes.

But these are all workarounds, and I do think there is room for improvement here. So I am going to use this issue as a feature request for improving this and similar scenarios.

Comment From: poutsma

In a test of a 1000 registered routes, I was able to make make the composition operators result in a stack overflow error, so I now consider this a bug instead of a enhancement, with a fix in 5.2.5 and 5.1.8.

Comment From: poutsma

Two fixes were applied:

• the composition operator was made more efficient by using concat instead of switchIfEmpty, see 54e2df2
• routes built by the router function builder are now no longer reduced in build(), but rather a passed on to a new, compositional router function implementation. see 7c4f031

Note that the former fix is sufficient to solve the stack trace problem, the latter is more an efficiency improvement that I did not back port to 5.1.x.

Comment From: imanushin

There is article to explain the issue (link, Russian translation).