CODEWITHSUNDEEP
spring-bootnettyspring-webfluxreactor
tkr
tkr

Reputation: 1371

Why does Spring Webflux only accepts 256 requests in parallel?

In the default configuration Spring Webflux seems to limit the number of parallel requests to 256.

My setup has this very simple controller:

@RestController
public class SimpleRestController {
  private final Log logger = LogFactory.getLog(getClass());

  private AtomicLong countEnter = new AtomicLong(0);
  private AtomicLong countExit = new AtomicLong(0);

  @GetMapping(value = "/delayed")
  public Mono<String> delayed() {
    logger.info("delayed ENTER " + countEnter.incrementAndGet());

    return Mono.just("result").delayElement(Duration.ofSeconds(60))

          .doOnNext(s -> logger.info("delayed EXIT " + countExit.incrementAndGet()));
  }
}

The configuration just enables WebFlux:

@SpringBootConfiguration
@EnableWebFlux
public class SearchServiceConfiguration {
}

The dependencies are only few:

  <properties>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
    <java.version>10</java.version>
  </properties>

  <dependencies>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-webflux</artifactId>
    </dependency>

    <dependency>
      <groupId>org.projectlombok</groupId>
      <artifactId>lombok</artifactId>
      <optional>true</optional>
    </dependency>
  </dependencies>

  <build>
    <plugins>
      <plugin>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-maven-plugin</artifactId>
      </plugin>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-compiler-plugin</artifactId>
        <version>3.8.0</version>
        <configuration>
          <source>10</source>
          <target>10</target>
          <encoding>UTF-8</encoding>
        </configuration>
      </plugin>
    </plugins>
  </build>

I call the endpoint with this script in parallel:

#!/usr/bin/env bash

for p in `seq 1 1000`;
do
    curl -s http://localhost:8080/delayed &
done

wait
echo "All done"

For the 257th request Resource temporarily unavailable is returned.

Which setting limits the amount of parallel requests?

This is the produced log output:

2018-10-26 14:27:27.253  INFO 23728 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/sleep],methods=[GET],produces=[application/stream+json]}" onto public java.lang.String controller.SimpleRestController.sleep() throws java.lang.InterruptedException
2018-10-26 14:27:27.253  INFO 23728 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/delayed],methods=[GET]}" onto public reactor.core.publisher.Mono<java.lang.String> controller.SimpleRestController.delayed()
2018-10-26 14:27:27.315  INFO 23728 --- [           main] o.s.w.r.r.m.a.ControllerMethodResolver   : Looking for @ControllerAdvice: org.springframework.boot.web.reactive.context.AnnotationConfigReactiveWebServerApplicationContext@3cdf2c61: startup date [Fri Oct 26 14:27:26 CEST 2018]; root of context hierarchy
2018-10-26 14:27:27.639  INFO 23728 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-10-26 14:27:27.938  INFO 23728 --- [ctor-http-nio-1] r.ipc.netty.tcp.BlockingNettyContext     : Started HttpServer on /0:0:0:0:0:0:0:0:8080
2018-10-26 14:27:27.939  INFO 23728 --- [           main] o.s.b.web.embedded.netty.NettyWebServer  : Netty started on port(s): 8080
2018-10-26 14:27:27.943  INFO 23728 --- [           main] d.h.s.s.SimpleApplication                : Started SimpleApplication in 1.548 seconds (JVM running for 2.396)
2018-10-26 14:27:34.295  INFO 23728 --- [ctor-http-nio-5] d.h.s.s.controller.SimpleRestController  : delayed ENTER 2
2018-10-26 14:27:34.295  INFO 23728 --- [ctor-http-nio-3] d.h.s.s.controller.SimpleRestController  : delayed ENTER 1
2018-10-26 14:27:34.295  INFO 23728 --- [ctor-http-nio-4] d.h.s.s.controller.SimpleRestController  : delayed ENTER 4
2018-10-26 14:27:34.295  INFO 23728 --- [ctor-http-nio-2] d.h.s.s.controller.SimpleRestController  : delayed ENTER 3
2018-10-26 14:27:34.324  INFO 23728 --- [ctor-http-nio-6] d.h.s.s.controller.SimpleRestController  : delayed ENTER 5
2018-10-26 14:27:34.351  INFO 23728 --- [ctor-http-nio-7] d.h.s.s.controller.SimpleRestController  : delayed ENTER 6
2018-10-26 14:27:34.381  INFO 23728 --- [ctor-http-nio-8] d.h.s.s.controller.SimpleRestController  : delayed ENTER 7
2018-10-26 14:27:34.413  INFO 23728 --- [ctor-http-nio-1] d.h.s.s.controller.SimpleRestController  : delayed ENTER 8
2018-10-26 14:27:34.438  INFO 23728 --- [ctor-http-nio-2] d.h.s.s.controller.SimpleRestController  : delayed ENTER 9
2018-10-26 14:27:34.466  INFO 23728 --- [ctor-http-nio-3] d.h.s.s.controller.SimpleRestController  : delayed ENTER 10
2018-10-26 14:27:34.497  INFO 23728 --- [ctor-http-nio-4] d.h.s.s.controller.SimpleRestController  : delayed ENTER 11
2018-10-26 14:27:34.526  INFO 23728 --- [ctor-http-nio-5] d.h.s.s.controller.SimpleRestController  : delayed ENTER 12
2018-10-26 14:27:34.561  INFO 23728 --- [ctor-http-nio-6] d.h.s.s.controller.SimpleRestController  : delayed ENTER 13
2018-10-26 14:27:34.594  INFO 23728 --- [ctor-http-nio-7] d.h.s.s.controller.SimpleRestController  : delayed ENTER 14
...
2018-10-26 14:27:42.675  INFO 23728 --- [ctor-http-nio-6] d.h.s.s.controller.SimpleRestController  : delayed ENTER 253
2018-10-26 14:27:42.711  INFO 23728 --- [ctor-http-nio-7] d.h.s.s.controller.SimpleRestController  : delayed ENTER 254
2018-10-26 14:27:42.745  INFO 23728 --- [ctor-http-nio-8] d.h.s.s.controller.SimpleRestController  : delayed ENTER 255
2018-10-26 14:27:42.774  INFO 23728 --- [ctor-http-nio-1] d.h.s.s.controller.SimpleRestController  : delayed ENTER 256
2018-10-26 14:28:04.312  INFO 23728 --- [     parallel-3] d.h.s.s.controller.SimpleRestController  : delayed EXIT 1
2018-10-26 14:28:04.312  INFO 23728 --- [     parallel-2] d.h.s.s.controller.SimpleRestController  : delayed EXIT 2
2018-10-26 14:28:04.321  INFO 23728 --- [     parallel-2] d.h.s.s.controller.SimpleRestController  : delayed EXIT 3
2018-10-26 14:28:04.321  INFO 23728 --- [     parallel-2] d.h.s.s.controller.SimpleRestController  : delayed EXIT 4
2018-10-26 14:28:04.333  INFO 23728 --- [     parallel-4] d.h.s.s.controller.SimpleRestController  : delayed EXIT 5
2018-10-26 14:28:04.359  INFO 23728 --- [     parallel-5] d.h.s.s.controller.SimpleRestController  : delayed EXIT 6
2018-10-26 14:28:04.389  INFO 23728 --- [     parallel-6] d.h.s.s.controller.SimpleRestController  : delayed EXIT 7
2018-10-26 14:28:04.421  INFO 23728 --- [     parallel-7] d.h.s.s.controller.SimpleRestController  : delayed EXIT 8
2018-10-26 14:28:04.446  INFO 23728 --- [     parallel-8] d.h.s.s.controller.SimpleRestController  : delayed EXIT 9
2018-10-26 14:28:04.474  INFO 23728 --- [     parallel-1] d.h.s.s.controller.SimpleRestController  : delayed EXIT 10
2018-10-26 14:28:04.505  INFO 23728 --- [     parallel-2] d.h.s.s.controller.SimpleRestController  : delayed EXIT 11
...
2018-10-26 14:28:12.570  INFO 23728 --- [     parallel-1] d.h.s.s.controller.SimpleRestController  : delayed EXIT 250
2018-10-26 14:28:12.607  INFO 23728 --- [     parallel-2] d.h.s.s.controller.SimpleRestController  : delayed EXIT 251
2018-10-26 14:28:12.643  INFO 23728 --- [     parallel-3] d.h.s.s.controller.SimpleRestController  : delayed EXIT 252
2018-10-26 14:28:12.683  INFO 23728 --- [     parallel-4] d.h.s.s.controller.SimpleRestController  : delayed EXIT 253
2018-10-26 14:28:12.719  INFO 23728 --- [     parallel-5] d.h.s.s.controller.SimpleRestController  : delayed EXIT 254
2018-10-26 14:28:12.752  INFO 23728 --- [     parallel-6] d.h.s.s.controller.SimpleRestController  : delayed EXIT 255
2018-10-26 14:28:12.782  INFO 23728 --- [     parallel-7] d.h.s.s.controller.SimpleRestController  : delayed EXIT 256

Upvotes: 12

Views: 4690

Answers (2)

Devon_C_Miller
Devon_C_Miller

Reputation: 16518

The server is not your limiting factor. That error indicates creating a background process failed due to a resource limitation. There are several possible causes:

  • memory - each process requires memory to load curl.
  • processes - there may be a limit on the number of processes you can create
  • open files - each process opens multiple "files". That's in quotes, because "files" include network connections and dynamic libraries loaded by curl. There is a system-wide limit on how many can be opened at once.

Upvotes: 4

Brian Clozel
Brian Clozel

Reputation: 59086

This is not what I'm seeing with my local setup. Changing your controller to the following does print "onNext 1" to "onNext 1000":

AtomicLong count = new AtomicLong(0);

@GetMapping("/delayed")
public Mono<String> delayed() {
    return Mono.just("result").delayElement(Duration.ofSeconds(30))
            .doOnNext(s -> {
                logger.info("onNext " + count.incrementAndGet());
            });
}

In one of your comments you're mentioning the CommonsRequestLoggingFilter, which is Servlet specific. This tells me you're not running a Spring WebFlux application but actually a Spring MVC application. If you're running Spring Boot and you have Spring MVC on the classpath, Spring Boot will configure a Spring MVC application for you.

By default, Spring MVC will use a SimpleAsyncTaskExecutor for scheduling async processing for those requests (Spring MVC supports reactive return types but will treat them as @Async requests, asynchronous but not non-blocking). I think the SimpleAsyncTaskExecutor has no concurrency limit by default. Maybe you've configured in your application a task executor that's limiting the concurrency to 256?

I've tried to reproduce that with a Spring MVC application and still get 999 requests processed and one resolved exception in the logs:

.w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.web.context.request.async.AsyncRequestTimeoutException]

Upvotes: 8

Related Questions