Обходной путь для медлительности первого запроса WebClient

Я использую WebClient в проекте Spring Boot MVC 2.1 и обнаружил, что первый запрос, сделанный клиентом, занимает до 6 секунд. Последующие запросы намного быстрее (~ 30 мс).

Существует закрытая проблема в Spring JIRA, в которой рекомендуется использовать Jetty в качестве Http-коннектора WebClient. Я попробовал этот подход, улучшив цифры, с первым запросом ~ 800 мс. На этот раз это улучшение, но это все еще далеко от RestTemplate, которое обычно занимает ‹200 мс.

Подход Netty (первый запрос 5 с):

Конф:

@Bean
public WebClient webClient() {
    return WebClient.create();
}

Использование:

private final WebClient webClient;

@GetMapping(value="/wc", produces = APPLICATION_JSON_UTF8_VALUE)
public Mono<String> findWc() throws URISyntaxException {
    URI uri = new URI("http://xxx");
    final Mono<String> response = webClient.get().uri(uri).retrieve().bodyToMono(String.class);
    return response;
}

Подход Jetty (первый запрос 800 мс):

Конф:

@Bean
public JettyResourceFactory resourceFactory() {
    return new JettyResourceFactory();
}

@Bean
public WebClient webClient() {
    ClientHttpConnector connector = new JettyClientHttpConnector(resourceFactory(), null);
    return WebClient.builder().clientConnector(connector).build();
}

Использование: то же, что и раньше.

Есть еще одна «проблема» с подходом Jetty. При выключении сервера всегда выдает следующее исключение:

27-Dec-2018 11:24:20.463 INFO [jetty-http@74305db9-65] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [org.eclipse.jetty.io.ManagedSelector$StopSelector]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
 java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.eclipse.jetty.io.ManagedSelector$StopSelector]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1348)
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1336)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1195)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1157)
    at java.lang.Class.getDeclaringClass0(Native Method)
    at java.lang.Class.getDeclaringClass(Class.java:1235)
    at java.lang.Class.getEnclosingClass(Class.java:1277)
    at java.lang.Class.getSimpleBinaryName(Class.java:1443)
    at java.lang.Class.getSimpleName(Class.java:1309)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.toString(ManagedSelector.java:534)
    at java.lang.String.valueOf(String.java:2994)
    at java.lang.StringBuilder.append(StringBuilder.java:131)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.getString(EatWhatYouKill.java:458)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.toStringLocked(EatWhatYouKill.java:447)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.toString(EatWhatYouKill.java:440)
    at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:299)
    at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:271)
    at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:233)
    at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:173)
    at org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:680)
    at org.eclipse.jetty.util.log.JettyAwareLogger.debug(JettyAwareLogger.java:224)
    at org.eclipse.jetty.util.log.Slf4jLog.debug(Slf4jLog.java:97)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:288)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
    at java.lang.Thread.run(Thread.java:748)

SLF4J: Failed toString() invocation on an object of type [org.eclipse.jetty.util.thread.strategy.EatWhatYouKill]
Reported exception:
java.lang.NoClassDefFoundError: org/eclipse/jetty/io/ManagedSelector$StopSelector
    at java.lang.Class.getDeclaringClass0(Native Method)
    at java.lang.Class.getDeclaringClass(Class.java:1235)
    at java.lang.Class.getEnclosingClass(Class.java:1277)
    at java.lang.Class.getSimpleBinaryName(Class.java:1443)
    at java.lang.Class.getSimpleName(Class.java:1309)
    at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.toString(ManagedSelector.java:534)
    at java.lang.String.valueOf(String.java:2994)
    at java.lang.StringBuilder.append(StringBuilder.java:131)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.getString(EatWhatYouKill.java:458)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.toStringLocked(EatWhatYouKill.java:447)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.toString(EatWhatYouKill.java:440)
    at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:299)
    at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:271)
    at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:233)
    at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:173)
    at org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:680)
    at org.eclipse.jetty.util.log.JettyAwareLogger.debug(JettyAwareLogger.java:224)
    at org.eclipse.jetty.util.log.Slf4jLog.debug(Slf4jLog.java:97)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:288)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.ClassNotFoundException: Illegal access: this web application instance has been stopped already. Could not load [org.eclipse.jetty.io.ManagedSelector$StopSelector]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1338)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1195)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1157)
    ... 25 more
Caused by: java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.eclipse.jetty.io.ManagedSelector$StopSelector]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1348)
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1336)
    ... 27 more
27-Dec-2018 11:24:20.467 INFO [jetty-http@74305db9-65] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.classic.spi.ThrowableProxy]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
 java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.classic.spi.ThrowableProxy]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1348)
    at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1336)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1195)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1157)
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
    at ch.qos.logback.classic.Logger.log(Logger.java:765)
    at org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:668)
    at org.eclipse.jetty.util.log.JettyAwareLogger.warn(JettyAwareLogger.java:474)
    at org.eclipse.jetty.util.log.Slf4jLog.warn(Slf4jLog.java:73)
    at org.eclipse.jetty.util.log.Slf4jLog.warn(Slf4jLog.java:67)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.execute(EatWhatYouKill.java:375)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:305)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
    at java.lang.Thread.run(Thread.java:748)

Exception in thread "jetty-http@74305db9-65" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
    at ch.qos.logback.classic.Logger.log(Logger.java:765)
    at org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:668)
    at org.eclipse.jetty.util.log.JettyAwareLogger.warn(JettyAwareLogger.java:474)
    at org.eclipse.jetty.util.log.Slf4jLog.warn(Slf4jLog.java:73)
    at org.eclipse.jetty.util.log.Slf4jLog.warn(Slf4jLog.java:67)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:740)
    at java.lang.Thread.run(Thread.java:748)

  1. Как я могу избежать этого исключения?

  2. Есть ли другой способ улучшить скорость первого запроса WebClient?


spring-boot jetty spring-webflux reactor-netty
person codependent    schedule 27.12.2018    source источник
comment
Вы пытались внедрить предварительно настроенный WebClient.Builder Spring Boot и создать свой клиент на его основе с помощью Netty?   -  person Alexander Pankin    schedule 27.12.2018
comment
Внедрение предварительно настроенного компоновщика, исключение все еще происходит   -  person codependent    schedule 27.12.2018
comment
6 секунд — безумное количество времени; ты хоть представляешь, где это время тратится? Вы должны поднять вопрос о проекте реактора-netty с журналами DEBUG и репро-проектом.   -  person Brian Clozel    schedule 28.12.2018
comment
Я только что загрузил пример проекта, чтобы воспроизвести проблему (github.com/codependent/slow-webclient-sample) и создал задачу (github.com/reactor/reactor-netty/ вопросы/560).   -  person codependent    schedule 28.12.2018
comment
Я столкнулся с той же проблемой. Вы пытались сделать фиктивный вызов при запуске приложения? Это не решает проблему, но может защитить 1-го пользователя от задержки   -  person hookumsnivy    schedule 28.03.2019
comment
Это может быть обходной путь, но нет ничего лучше, чем фактическое решение. Я надеюсь, что команда Netty скоро это исправит...   -  person codependent    schedule 28.03.2019

Ответы (1)


arrow_upward
0
arrow_downward

Мы обновили Spring Boot до версии 2.4.2 с Reactor-Netty 1.0.3, но по-прежнему сталкиваемся с этой проблемой. Вот наша обновленная конфигурация:

   @Bean
    public WebClient createWebClient(WebClient.Builder webClientBuilder) {
        log.info("Initializing WebClient Bean");

        final int timeoutInMillis = Long.valueOf(TimeUnit.SECONDS.toMillis(timeout)).intValue();
        final HttpClient httpClient = HttpClient.create()
                .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, timeoutInMillis)
                .responseTimeout(Duration.ofMillis(timeoutInMillis))
                .doOnConnected(conn ->
                        conn.addHandlerLast(new ReadTimeoutHandler(timeoutInMillis, TimeUnit.MILLISECONDS))
                                .addHandlerLast(new WriteTimeoutHandler(timeoutInMillis, TimeUnit.MILLISECONDS)));
        final ClientHttpConnector connector = new ReactorClientHttpConnector(httpClient);
        final WebClient webClient = webClientBuilder
                .clientConnector(connector)
                .defaultHeader("x-clientname", clientname)
                .build();

        httpClient.warmup().block();
        log.info("WebClient initialized");

        return webClient;
    }

Наш звонок с WebClient:

  ResoponseObject doCall() {
        return this.webClient
                .get()
                .uri("http://***.de/api/rest/***")
                .accept(MediaType.APPLICATION_JSON)
                .retrieve()
                .bodyToMono(ResponseObject.class)
                .block();
    }

При включенной отладке через application.yaml: logging.level.reactor.netty: debug

Теперь мы видим это во время запуска приложения:

2021-02-10 17:02:31,922 INFO  d.t.e.b.c.c.WebClientAutoConfiguration - Initializing WebClient Bean 
2021-02-10 17:02:31,959 DEBUG r.n.r.DefaultLoopIOUring - Default io_uring support : false 
2021-02-10 17:02:31,967 DEBUG r.n.r.DefaultLoopEpoll - Default Epoll support : true 
2021-02-10 17:02:31,997 INFO  d.t.e.b.c.c.WebClientAutoConfiguration - WebClient initialized

Это должно быть признаком того, что прогрев работает, как ожидалось?

Но по первому запросу это происходит:

2021-02-10 17:05:16,045 DEBUG o.s.w.r.f.c.ExchangeFunctions - [73d400c8] HTTP GET http://***.de/api/rest/***
2021-02-10 17:05:16,050 DEBUG r.n.r.PooledConnectionProvider - Creating a new [http] client pool [PoolFactory{evictionInterval=PT0S, leasingStrategy=fifo, maxConnections=500, maxIdleTime=-1, maxLifeTime=-1, metricsEnabled=false, pendingAcquireMaxCount=1000, pendingAcquireTimeout=45000}] for [***.de/<unresolved>:80] 
2021-02-10 17:05:29,619 DEBUG r.n.r.DefaultPooledConnectionProvider - [id: 0x71b840f4] Created a new pooled channel, now 1 active connections and 0 inactive connections 
2021-02-10 17:05:29,635 DEBUG r.n.t.TransportConfig - [id: 0x71b840f4] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 
...

В нашем случае проблема заключается в создании пула клиентов. На приличной машине это занимает около 13 секунд.

Можете ли вы дать нам какой-либо комментарий по этому поводу? Это очень нас расстраивает.

Большое спасибо!

person Benjamin    schedule 10.02.2021
comment
ты решил эту проблему? - person kospi; 30.07.2021