Prevent blocking DeferredResult

Question

I have a method which blocks the thread and then returns a value. In order to prevent the web server from getting exhausted with blocked threads, I planned to use DeferredResult. I tried to demonstrate it by setting the server.tomcat.max-threads=1 in application.properties file. But when I hit URL multiple times from my browser, the behavior is still blocking. I am aware of the @Async annotation, which I can use on my blocking method, but what happens is that the request ends without any result.

My expectation is, the web server must entertain multiple requests even if the max-thread is set to 1. Maybe I am executing it incorrectly. So, I would request you to correct me. Following is my code. I have started three Http Request at the same time but the behavior appears synchronous. I am using Spring Boot v2.3.3

UPDATE 1:

I have changed my testing procedure. Instead of hitting 3 requests, I have hit 10. Now, after 4 requests are fulfilled by the web server synchronously, the remaining requests are entertained by the web server in a work stealing fashion. This is good, but I want the work stealing behavior to start immediately instead of waiting for multiple requests.

I have also tried Spring Boot's default and a custom AsyncTaskExecutor supplied to the CompletableFuture but the behavior remained the same when no TaskExecutor is provided.

TaskExecutor:

    @Bean(name = "threadPoolExecutor")
    public AsyncTaskExecutor getAsyncExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(7);
        executor.setMaxPoolSize(42);
        executor.setQueueCapacity(11);
        executor.setThreadNamePrefix("MyExecutor-");
        executor.initialize();
        return executor;
    }

Controller:

@RestController
public class DeferredController {

    private static final Logger LOGGER = LoggerFactory.getLogger(DeferredController.class);
    @Autowired
    private MyBlockingService blockingService;
    @Autowired
    @Qualifier("threadPoolExecutor")
    private AsyncTaskExecutor taskExecutor;

    @GetMapping("/home")
    public DeferredResult<String> home() {
        int randomId = (int) (Math.random() * 1000);
        LOGGER.info("Request received for id: {}", randomId);
        DeferredResult<String> result = new DeferredResult<>(6000L);
        result.onTimeout(() -> result.setErrorResult("Timeout"));
        CompletableFuture
                .supplyAsync(() -> blockingService.execute(randomId), taskExecutor)
                .whenCompleteAsync((output, throwable) -> {
                    if (output != null || !output.equals("")) {
                        result.setResult(output);
                    } else {
                        result.setErrorResult(throwable);
                    }
                });
        LOGGER.info("Servlet Thread released for id: {}", randomId);
        return result;
    }
}

Service:

@Service
public class MyBlockingService {

    private static final Logger LOGGER = LoggerFactory.getLogger(MyBlockingService.class);

    public String execute(int id) {
        LOGGER.info("Blocking Service start: {}", id);
        try {
            Thread.sleep(5000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        LOGGER.info("---- Blocking Service end: {} ----", id);
        return "Done: " + id;
    }
}

Logs:

2022-04-12 10:45:02.146  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 844
2022-04-12 10:45:02.149  INFO [onPool-worker-1] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 844
2022-04-12 10:45:02.150  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 844
2022-04-12 10:45:07.151  INFO [onPool-worker-1] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 844 ----
2022-04-12 10:45:07.214  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 624
2022-04-12 10:45:07.214  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 624
2022-04-12 10:45:07.214  INFO [onPool-worker-1] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 624
2022-04-12 10:45:12.223  INFO [onPool-worker-1] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 624 ----
2022-04-12 10:45:12.240  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 711
2022-04-12 10:45:12.240  INFO [onPool-worker-1] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 711
2022-04-12 10:45:12.240  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 711
2022-04-12 10:45:17.245  INFO [onPool-worker-1] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 711 ----

Logs based on UPDATE 1:

2022-04-12 12:53:16.781  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 782
2022-04-12 12:53:16.783  INFO [   MyExecutor-1] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 782
2022-04-12 12:53:16.783  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 782
2022-04-12 12:53:21.795  INFO [   MyExecutor-1] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 782 ----
2022-04-12 12:53:21.836  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 774
2022-04-12 12:53:21.836  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 774
2022-04-12 12:53:21.836  INFO [   MyExecutor-2] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 774
2022-04-12 12:53:26.837  INFO [   MyExecutor-2] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 774 ----
2022-04-12 12:53:26.851  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 381
2022-04-12 12:53:26.852  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 381
2022-04-12 12:53:26.853  INFO [   MyExecutor-3] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 381
2022-04-12 12:53:31.870  INFO [   MyExecutor-3] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 381 ----
2022-04-12 12:53:31.883  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 296
2022-04-12 12:53:31.883  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 296
2022-04-12 12:53:31.883  INFO [   MyExecutor-4] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 296
2022-04-12 12:53:36.892  INFO [   MyExecutor-4] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 296 ----
2022-04-12 12:53:36.904  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 149
2022-04-12 12:53:36.904  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 149
2022-04-12 12:53:36.904  INFO [   MyExecutor-5] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 149
2022-04-12 12:53:38.989  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 132
2022-04-12 12:53:38.990  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 132
2022-04-12 12:53:38.991  INFO [   MyExecutor-6] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 132
2022-04-12 12:53:39.431  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 119
2022-04-12 12:53:39.431  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 119
2022-04-12 12:53:39.432  INFO [   MyExecutor-7] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 119
2022-04-12 12:53:39.872  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 308
2022-04-12 12:53:39.872  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 308
2022-04-12 12:53:39.872  INFO [   MyExecutor-1] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 308
2022-04-12 12:53:40.294  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 734
2022-04-12 12:53:40.294  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 734
2022-04-12 12:53:40.294  INFO [   MyExecutor-2] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 734
2022-04-12 12:53:40.838  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 601
2022-04-12 12:53:40.839  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 601
2022-04-12 12:53:40.839  INFO [   MyExecutor-3] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 601
2022-04-12 12:53:41.916  INFO [   MyExecutor-5] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 149 ----
2022-04-12 12:53:41.931  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 773
2022-04-12 12:53:41.931  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 773
2022-04-12 12:53:41.931  INFO [   MyExecutor-4] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 773
2022-04-12 12:53:44.000  INFO [   MyExecutor-6] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 132 ----
2022-04-12 12:53:44.016  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 98
2022-04-12 12:53:44.016  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 98
2022-04-12 12:53:44.016  INFO [   MyExecutor-5] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 98
2022-04-12 12:53:44.436  INFO [   MyExecutor-7] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 119 ----
2022-04-12 12:53:44.448  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Request received for id: 456
2022-04-12 12:53:44.449  INFO [nio-8080-exec-1] c.s.d.s.c.DeferredController   :  Servlet Thread released for id: 456
2022-04-12 12:53:44.449  INFO [   MyExecutor-6] c.s.d.s.c.MyBlockingService    :  Blocking Service start: 456
2022-04-12 12:53:44.887  INFO [   MyExecutor-1] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 308 ----
2022-04-12 12:53:45.311  INFO [   MyExecutor-2] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 734 ----
2022-04-12 12:53:45.841  INFO [   MyExecutor-3] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 601 ----
2022-04-12 12:53:46.933  INFO [   MyExecutor-4] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 773 ----
2022-04-12 12:53:49.022  INFO [   MyExecutor-5] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 98 ----
2022-04-12 12:53:49.458  INFO [   MyExecutor-6] c.s.d.s.c.MyBlockingService    :  ---- Blocking Service end: 456 ----

You should have a threadpool to supply the async work on. Inject an `AsynTaskExecutor` (which is an interface) into your controller and pass that to the `supplyAsync` method of the `CompletableFuture`. Spring Boot will by default configure a `TaskExecutor` for you, or you can provide your own . — M. Deinum, Apr 12 '22 at 06:18
@M.Deinum Thank you for the suggestion. I have tried this implementation and the behavior remained the same. I have changed my testing scenario a bit. I have hit 10 requests now and after 4 requests are fulfilled by the web server, the work stealing behavior has showed up. This is good but I want the work stealing behavior to be kicked in immedaitely. — sam, Apr 12 '22 at 07:28
Judging from this you apparently configured your own `TaskExecutor` but haven't specified a queue size. — M. Deinum, Apr 12 '22 at 07:50
@M.Deinum My corePoolSize is 7, maxPoolSize 42 and Queue size is 11. I have updated the question. — sam, Apr 12 '22 at 08:04
I don't see the issue here. It looks to do exactly what you programmed to do. Request is received, handled in the background, while being handled thread is released. So I wonder what you think is wrong and how you are writing your tests. — M. Deinum, Apr 12 '22 at 08:13
@M.Deinum Probably my assumption is incorrect. Thank you for your valuable time. — sam, Apr 18 '22 at 08:03

Prevent blocking DeferredResult

0 Answers0