WebClient's first request is slow [SPR-17200]

[spring-issuemaster]

Krzysztof Slonka opened SPR-17200 and commented

I discovered an issue with first request and shared state in WebClient. In short, the first request takes a lot of time to complete (~300 ms on my machine) compared to the following requests (~5 ms).  The performance compared to RestTemplate is a bit problematic in case of integration tests with WireMock. I described more details in a repository with code examples: https://github.com/slonka/webclient-debug

 

I'd be grateful for some insights whether this can be improved via configuration or changes to WebClient source code that would initialize static fields eagerly before first request.

 

Please let me know if I can provide any more information.

---

Affects: 5.0.8

Reference URL: https://github.com/slonka/webclient-debug

[spring-issuemaster]

Brian Clozel commented

Hello Krzysztof Slonka,

First, thanks for this very detailed report and repro project.

I ran your project with some modifications to the stats engine, and I also see slower calls for the first requests.

I've changed the classfiletransformer to also spy on reactor netty 0.7 classes, adding "reactor/ipc/netty"; here are the results:
|Method name|Avg time|
|:---|:---|
|reactor.ipc.netty.channel.ContextHandler.accept(java.lang.Object)|71.78|
|org.springframework.web.reactive.function.client.DefaultClientResponse.bodyToMono(java.lang.Class)|57.57|
|org.springframework.web.reactive.function.BodyExtractors.lambda$toMono|55.33|
|org.springframework.web.util.DefaultUriBuilderFactory$DefaultUriBuilder.build(java.lang.Object[])|47.07|
|org.springframework.web.util.UriComponents.encode()|35.70|
|org.springframework.web.util.HierarchicalUriComponents.encode(java.nio.charset.Charset)|35.55|
|reactor.ipc.netty.http.client.HttpClient$TcpBridgeClient.accept(java.lang.Object,java.lang.Object)|28.61|

 

It seems that a lot of comes from lazy initialization of the Netty pipeline/context/connection pool. Once this is done, the client is reusing existing connections in the connection pool. Also, depending on the platform, Netty will use native bindings (such as epoll on Linux), which could explain discrepancies between platforms. I haven't tried instrumenting Netty itself.

Spring's UriComponents is still showing up here, and it's got nothing to do with Reactor nor Netty.

I've tried doing the same thing with Spring Boot 2.1.0.M1, since many changes were done in reactor netty 0.8 (a total rewrite of the client library) and Spring WebFlux itself. This time, we need to instrument "reactor/netty/http", since classes were relocated in the meantime.

Here are the results:
|Method name|Avg time|
|:---|:---|
|reactor.netty.resources.PooledConnectionProvider$Pool.channelCreated|99.56|
|org.springframework.http.client.reactive.ReactorClientHttpConnector.connect|98.24|
|reactor.netty.http.client.HttpClientOperations.onInboundNext|73.83|
|org.springframework.web.reactive.function.client.DefaultClientResponse.bodyToMono|50.80|
|org.springframework.web.reactive.function.BodyExtractors.lambda$toMono$2|48.38|
|reactor.netty.http.client.HttpClientFinalizer.connect()|27.78|

I think the API changes are making things more obvious that the first connection, channel setup and first response are at play here. The UriComponents is not showing anymore here, since we've changed things around that in Spring Framework 5.1.

• Could you confirm that reactor netty is playing an important part here?
• Could you try this as well with Spring Boot 2.1.0.M2?
• Could you try again with RestTemplate, but this time using the Netty client request factory instead?

Note that as of Spring Framework 5.1, you can also choose Jetty as a driver for WebClient; this client might have a different runtime profile that suits you best (you'll be able to test that in the next Spring Boot 2.1 milestone release).

Given the current data, I'm not seeing anything we can do in the Spring Framework to improve that. Reactor Netty might be able to improve things, but Netty's model is probably important here. 

[spring-issuemaster]

Krzysztof Slonka commented

Hello :)

Thanks for your response. 

"Could you confirm that reactor netty is playing an important part here?"

I've added "reactor/ipc/netty" to instrumented libraries and the results are as follows:
|first call|mean|std|
|reactor.ipc.netty.resources.DefaultPoolResources$Pool.channelCreated(io.netty.channel.Channel)|212.7690476|14.81781336|
|reactor.ipc.netty.channel.ContextHandler.accept(java.lang.Object)|101.7739683|7.98404849|
|org.springframework.web.reactive.function.client.DefaultWebClient$DefaultResponseSpec.lambda$bodyToMono$0(java.lang.Class,org.springframework.web.reactive.function.client.ClientResponse)|54.63619048|3.988940834|
|reactor.ipc.netty.channel.ContextHandler.createOperations(io.netty.channel.Channel,java.lang.Object)|50.50714286|4.970028402|
|org.springframework.web.reactive.function.client.DefaultClientResponse.bodyToMono(java.lang.Class)|49.79634921|3.66674039|
|reactor.ipc.netty.http.client.HttpClient$TcpBridgeClient.lambda$doHandler$0(java.util.function.Consumer,java.util.function.BiFunction,io.netty.channel.socket.SocketChannel,reactor.ipc.netty.channel.ContextHandler,java.lang.Object)|49.66761905|4.920230255|
|reactor.ipc.netty.channel.ContextHandler.accept(io.netty.channel.Channel)|49.5052381|3.196421539|
|org.springframework.web.reactive.function.client.DefaultClientResponse.body(org.springframework.web.reactive.function.BodyExtractor)|48.85031746|3.611904905|
|org.springframework.web.reactive.function.BodyExtractors.lambda$toMono$2(org.springframework.core.ResolvableType,org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context)|47.55047619|3.455702638|
|org.springframework.web.reactive.function.BodyExtractors.readWithMessageReaders(org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context,org.springframework.core.ResolvableType,java.util.function.Function,java.util.function.Function,java.util.function.Supplier)|46.56301587|3.393362164|
|reactor.ipc.netty.http.client.HttpClient$TcpBridgeClient.accept(java.lang.Object,java.lang.Object)|35.92587302|2.843385884|
|org.springframework.web.util.DefaultUriBuilderFactory.expand(java.lang.String,java.lang.Object[])|33.5431746|15.02812737|
|reactor.ipc.netty.http.client.MonoHttpClientResponse$HttpClientHandler.apply(java.lang.Object,java.lang.Object)|30.96809524|3.320205032|
|reactor.ipc.netty.http.client.MonoHttpClientResponse$HttpClientHandler.apply(reactor.ipc.netty.NettyInbound,reactor.ipc.netty.NettyOutbound)|30.89269841|3.312456148|
|reactor.ipc.netty.http.client.HttpClient.lambda$handler$4(java.util.function.Function,reactor.ipc.netty.http.client.HttpClientRequest)|29.9668254|3.243311959|
|org.springframework.http.client.reactive.ReactorClientHttpConnector.lambda$connect$1(java.util.function.Function,org.springframework.http.HttpMethod,java.net.URI,reactor.ipc.netty.http.client.HttpClientRequest)|29.82793651|3.233335866|
|reactor.ipc.netty.http.client.HttpClient$TcpBridgeClient.accept(io.netty.channel.ChannelPipeline,reactor.ipc.netty.channel.ContextHandler)|27.09015873|2.059302927|
|org.springframework.web.reactive.function.BodyExtractors.lambda$null$0(org.springframework.web.reactive.function.BodyExtractor$Context,org.springframework.http.ReactiveHttpInputMessage,org.springframework.core.ResolvableType,org.springframework.http.codec.HttpMessageReader)|26.76952381|2.162671356|
|org.springframework.http.codec.DecoderHttpMessageReader.readMono(org.springframework.core.ResolvableType,org.springframework.http.ReactiveHttpInputMessage,java.util.Map)|26.57936508|2.148526164|
|reactor.ipc.netty.FutureMono$DeferredFutureMono.subscribe(reactor.core.CoreSubscriber)|26.17206349|2.215013819|
|org.springframework.web.util.DefaultUriBuilderFactory$DefaultUriBuilder.build(java.lang.Object[])|22.89968254|2.806018457|
|reactor.ipc.netty.http.client.HttpClient$TcpBridgeClient.doHandler(java.util.function.BiFunction,reactor.core.publisher.MonoSink,boolean,java.net.SocketAddress,io.netty.channel.pool.ChannelPool,java.util.function.Consumer)|19.81825397|3.6185398|
|reactor.ipc.netty.resources.LoopResources.preferNative()|17.03873016|5.460715545|

 

As you can see that "reactor.ipc.netty" methods are on top.

 

"Could you try this as well with Spring Boot 2.1.0.M2?"

Yes, and the results are as follows:
|first call|mean|std|
|reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.subscribe(reactor.core.CoreSubscriber)|136.6201053|17.68037809|
|org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(org.springframework.web.reactive.function.client.ClientRequest)|113.4696842|8.064990548|
|org.springframework.http.client.reactive.ReactorClientHttpConnector.connect(org.springframework.http.HttpMethod,java.net.URI,java.util.function.Function)|111.1238947|7.938923869|
|reactor.netty.http.client.HttpClientFinalizer.responseConnection(java.util.function.BiFunction)|99.03463158|7.357937756|
|reactor.netty.http.client.HttpClientOperations.onInboundNext(io.netty.channel.ChannelHandlerContext,java.lang.Object)|90.11305263|9.326849874|
|reactor.netty.http.client.HttpClientConnect$HttpObserver.onStateChange(reactor.netty.Connection,reactor.netty.ConnectionObserver$State)|89.61936842|10.79728629|
|reactor.netty.http.client.HttpClientConnect$HttpObserver.onStateChange(reactor.netty.Connection,reactor.netty.ConnectionObserver$State)|85.50715789|9.055751027|
|org.springframework.web.reactive.function.client.DefaultWebClient$DefaultResponseSpec.lambda$bodyToMono$0(java.lang.Class,org.springframework.web.reactive.function.client.ClientResponse)|61.05568421|7.059406961|
|org.springframework.web.reactive.function.client.DefaultClientResponse.bodyToMono(java.lang.Class)|54.13610526|6.584634313|
|org.springframework.web.reactive.function.client.DefaultClientResponse.body(org.springframework.web.reactive.function.BodyExtractor)|52.95010526|6.510936952|
|org.springframework.web.reactive.function.BodyExtractors.lambda$toMono$2(org.springframework.core.ResolvableType,org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context)|50.78589474|6.329689523|
|org.springframework.web.reactive.function.BodyExtractors.readWithMessageReaders(org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context,org.springframework.core.ResolvableType,java.util.function.Function,java.util.function.Function,java.util.function.Supplier)|49.28178947|6.198136389|
|reactor.netty.http.client.HttpClientConnect$HttpObserver.lambda$onStateChange$0(reactor.netty.Connection)|33.90673684|6.831755333|
|reactor.netty.http.client.HttpClientConnect$HttpClientHandler.requestWithBody(reactor.netty.http.client.HttpClientOperations)|33.81873684|6.830053131|
|org.springframework.http.client.reactive.ReactorClientHttpConnector.lambda$connect$1(java.util.function.Function,org.springframework.http.HttpMethod,java.net.URI,reactor.netty.http.client.HttpClientRequest,reactor.netty.NettyOutbound)|32.11968421|6.799586435|
|org.springframework.web.reactive.function.BodyExtractors.lambda$null$0(org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context,org.springframework.core.ResolvableType,org.springframework.http.codec.HttpMessageReader)|28.04021053|3.744217712|
|org.springframework.web.reactive.function.BodyExtractors.readToMono(org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context,org.springframework.core.ResolvableType,org.springframework.http.codec.HttpMessageReader)|27.97589474|3.739370196|
|org.springframework.web.reactive.function.BodyExtractors.lambda$readToMono$16(org.springframework.http.codec.HttpMessageReader,org.springframework.core.ResolvableType,org.springframework.http.ReactiveHttpInputMessage,org.springframework.web.reactive.function.BodyExtractor$Context)|26.83915789|3.601164333|
|org.springframework.http.codec.DecoderHttpMessageReader.readMono(org.springframework.core.ResolvableType,org.springframework.http.ReactiveHttpInputMessage,java.util.Map)|26.52105263|3.558142766|
|org.springframework.http.client.reactive.ReactorClientHttpConnector.adaptRequest(org.springframework.http.HttpMethod,java.net.URI,reactor.netty.http.client.HttpClientRequest,reactor.netty.NettyOutbound)|26.02726316|6.562909086|
|reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.lambda$subscribe$0(reactor.netty.http.client.HttpClientConnect$HttpClientHandler,reactor.netty.ConnectionObserver,io.netty.channel.Channel)|25.74768421|3.218564392|
|reactor.netty.http.HttpOperations.lambda$then$0()|25.47968421|3.431308314|
|reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.lambda$subscribe$1(reactor.netty.http.client.HttpClientConnect$HttpClientHandler,reactor.netty.tcp.SslProvider,io.netty.bootstrap.Bootstrap,reactor.core.publisher.MonoSink)|23.93747368|2.527726654|
|reactor.netty.http.client.HttpClientOperations.onOutboundComplete()|22.53221053|3.60759905|
|org.springframework.core.codec.AbstractDataBufferDecoder.decodeToMono(org.reactivestreams.Publisher,org.springframework.core.ResolvableType,org.springframework.util.MimeType,java.util.Map)|22.40126316|3.149687116|
|reactor.netty.http.client.HttpClientFinalizer.connect()|22.09852632|1.983232857|
|reactor.netty.http.client.HttpClientOperations.isWebsocket()|21.29957895|3.513818411|
|reactor.netty.http.client.HttpClientOperations.onInboundNext(io.netty.channel.ChannelHandlerContext,java.lang.Object)|19.47210526|4.537379001|
|org.springframework.http.client.reactive.ReactorClientHttpResponse.lambda$getBody$0(io.netty.buffer.ByteBuf)|19.22578947|4.513438316|
|org.springframework.core.io.buffer.NettyDataBufferFactory.wrap(io.netty.buffer.ByteBuf)|19.14789474|4.506127499|
|reactor.netty.http.client.HttpClientConnect.lambda$static$0(reactor.netty.Connection,reactor.netty.ConnectionObserver,java.lang.Object)|17.27768421|6.120580546|

Not much changed in terms of timing, but URI Builder is no longer there (as you pointed out).

 

"Could you try again with RestTemplate, but this time using the Netty client request factory instead?"

When using Netty4ClientHttpRequestFactory for RestTemplate, first request takes ~300 ms on my machine which is similar to WebClient.

 

When using JettyClientHttpConnector first request takes ~200 ms, which is better.

—

Considering everything we discussed here, what do you suggest using?

[spring-issuemaster]

Brian Clozel commented

Thanks Krzysztof Slonka!

We've now come to the conclusion that this is tied to Netty's runtime model more than Spring itself. We're always looking into optimizations but this one looks like a tradeoff more than something we can work on.

My previous comment mentioned Jetty as an alternative client library, and this might be interesting if its runtime model suits you better.