ACH
Reputation: 195
Number of parallel threads processing is capped to 10 with Spring Batch
I have the following task executor which is used to run a 10s sleep time tasklet with partitions:
<bean id="taskExecutor" class="org.springframework.core.task.SimpleAsyncTaskExecutor">
<property name="concurrencyLimit" value="${concurrency_limit}"/>
</bean>
<batch:step id="stepWait">
<batch:partition partitioner="partitionerWait">
<batch:handler grid-size="1" task-executor="taskExecutor"/>
<batch:step>
<batch:tasklet ref="taskletWait"/>
</batch:step>
</batch:partition>
</batch:step>
public class TaskletWait implements Tasklet {
private final Logger logger = LoggerFactory.getLogger(TaskletWait.class);
@Override
public RepeatStatus execute(StepContribution contribution, ChunkContext chunkContext){
String stepName = contribution.getStepExecution().getStepName();
logger.info("starting step: " + stepName);
try {
TimeUnit.SECONDS.sleep(10);
} catch (InterruptedException e) {
logger.error(e.getMessage());
}
contribution.setExitStatus(ExitStatus.COMPLETED);
return RepeatStatus.FINISHED;
}
}
The number of threads running in parallel is correctly adjusting with the value I set in application.properties, until it reaches 10. Whether I set 10, 15, 25 or 100, only 10 threads run in parallel. Example with concurrency_limit=15:
2021-07-06 13:31:34.937 INFO [SimpleAsyncTaskExecutor-12] [execute] starting step: stepWait:4
2021-07-06 13:31:34.937 INFO [SimpleAsyncTaskExecutor-2] [execute] starting step: stepWait:30
2021-07-06 13:31:34.937 INFO [SimpleAsyncTaskExecutor-1] [execute] starting step: stepWait:26
2021-07-06 13:31:34.937 INFO [SimpleAsyncTaskExecutor-9] [execute] starting step: stepWait:17
2021-07-06 13:31:34.937 INFO [SimpleAsyncTaskExecutor-3] [execute] starting step: stepWait:15
2021-07-06 13:31:34.937 INFO [SimpleAsyncTaskExecutor-8] [execute] starting step: stepWait:11
2021-07-06 13:31:34.939 INFO [SimpleAsyncTaskExecutor-10] [execute] starting step: stepWait:7
2021-07-06 13:31:34.940 INFO [SimpleAsyncTaskExecutor-5] [execute] starting step: stepWait:1
2021-07-06 13:31:34.941 INFO [SimpleAsyncTaskExecutor-15] [execute] starting step: stepWait:5
2021-07-06 13:31:34.943 INFO [SimpleAsyncTaskExecutor-14] [execute] starting step: stepWait:23
2021-07-06 13:31:44.941 INFO [SimpleAsyncTaskExecutor-6] [execute] starting step: stepWait:32
2021-07-06 13:31:44.941 INFO [SimpleAsyncTaskExecutor-4] [execute] starting step: stepWait:19
2021-07-06 13:31:44.941 INFO [SimpleAsyncTaskExecutor-7] [execute] starting step: stepWait:16
2021-07-06 13:31:44.942 INFO [SimpleAsyncTaskExecutor-11] [execute] starting step: stepWait:13
2021-07-06 13:31:44.943 INFO [SimpleAsyncTaskExecutor-13] [execute] starting step: stepWait:20
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-2] [execute] Step: [stepWait:30] executed in 10s21ms
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-8] [execute] Step: [stepWait:11] executed in 10s20ms
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-5] [execute] Step: [stepWait:1] executed in 10s21ms
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-9] [execute] Step: [stepWait:17] executed in 10s20ms
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-14] [execute] Step: [stepWait:23] executed in 10s18ms
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-10] [execute] Step: [stepWait:7] executed in 10s20ms
2021-07-06 13:31:44.950 INFO [SimpleAsyncTaskExecutor-1] [execute] Step: [stepWait:26] executed in 10s22ms
2021-07-06 13:31:44.951 INFO [SimpleAsyncTaskExecutor-3] [execute] Step: [stepWait:15] executed in 10s22ms
2021-07-06 13:31:44.958 INFO [SimpleAsyncTaskExecutor-12] [execute] Step: [stepWait:4] executed in 10s29ms
2021-07-06 13:31:44.959 INFO [SimpleAsyncTaskExecutor-15] [execute] Step: [stepWait:5] executed in 10s27ms
2021-07-06 13:31:44.961 INFO [SimpleAsyncTaskExecutor-16] [execute] starting step: stepWait:6
2021-07-06 13:31:44.962 INFO [SimpleAsyncTaskExecutor-17] [execute] starting step: stepWait:9
2021-07-06 13:31:44.963 INFO [SimpleAsyncTaskExecutor-18] [execute] starting step: stepWait:24
2021-07-06 13:31:44.963 INFO [SimpleAsyncTaskExecutor-19] [execute] starting step: stepWait:27
2021-07-06 13:31:44.963 INFO [SimpleAsyncTaskExecutor-20] [execute] starting step: stepWait:3
2021-07-06 13:31:54.944 INFO [SimpleAsyncTaskExecutor-21] [execute] starting step: stepWait:10
2021-07-06 13:31:54.946 INFO [SimpleAsyncTaskExecutor-23] [execute] starting step: stepWait:33
2021-07-06 13:31:54.947 INFO [SimpleAsyncTaskExecutor-22] [execute] starting step: stepWait:12
2021-07-06 13:31:54.948 INFO [SimpleAsyncTaskExecutor-7] [execute] Step: [stepWait:16] executed in 20s19ms
2021-07-06 13:31:54.951 INFO [SimpleAsyncTaskExecutor-13] [execute] Step: [stepWait:20] executed in 20s20ms
2021-07-06 13:31:54.952 INFO [SimpleAsyncTaskExecutor-6] [execute] Step: [stepWait:32] executed in 20s22ms
2021-07-06 13:31:54.954 INFO [SimpleAsyncTaskExecutor-24] [execute] starting step: stepWait:2
2021-07-06 13:31:54.954 INFO [SimpleAsyncTaskExecutor-4] [execute] Step: [stepWait:19] executed in 20s25ms
2021-07-06 13:31:54.955 INFO [SimpleAsyncTaskExecutor-11] [execute] Step: [stepWait:13] executed in 20s25ms
2021-07-06 13:31:54.957 INFO [SimpleAsyncTaskExecutor-25] [execute] starting step: stepWait:22
2021-07-06 13:31:54.967 INFO [SimpleAsyncTaskExecutor-16] [execute] Step: [stepWait:6] executed in 10s13ms
2021-07-06 13:31:54.968 INFO [SimpleAsyncTaskExecutor-17] [execute] Step: [stepWait:9] executed in 10s13ms
[...]
11th to 15th seems to be started but wait for one thread to be over to actually execute, it can be seen with the time execution of 20s for them.
Current logs are generated with java 11 on windows.
I have tried with org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor instead of SimpleAsyncTaskExecutor but same result.
I have tried both on Windows and Linux but same result
What could cause this limitation and how can I make it run more than 10 threads in parallel?
EDIT: I'm adding debug logs of ConcurrencyThrottleSupport
2021-07-06 17:24:04.860 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 0
2021-07-06 17:24:04.860 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 1
2021-07-06 17:24:04.861 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 2
2021-07-06 17:24:04.861 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 3
2021-07-06 17:24:04.861 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 4
2021-07-06 17:24:04.862 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 5
2021-07-06 17:24:04.864 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 6
2021-07-06 17:24:04.864 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 7
2021-07-06 17:24:04.865 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 8
2021-07-06 17:24:04.865 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 9
2021-07-06 17:24:04.866 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 10
2021-07-06 17:24:04.866 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 11
2021-07-06 17:24:04.866 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 12
2021-07-06 17:24:04.867 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 13
2021-07-06 17:24:04.867 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 14
2021-07-06 17:24:04.868 DEBUG [main] [beforeAccess] Concurrency count 15 has reached limit 15 - blocking
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-9] [execute] starting step: wait:3
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-7] [execute] starting step: wait:7
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-2] [execute] starting step: wait:11
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-3] [execute] starting step: wait:2
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-5] [execute] starting step: wait:16
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-12] [execute] starting step: wait:4
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-10] [execute] starting step: wait:34
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-11] [execute] starting step: wait:27
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-4] [execute] starting step: wait:18
2021-07-06 17:24:04.869 INFO [SimpleAsyncTaskExecutor-1] [execute] starting step: wait:29
2021-07-06 17:24:14.873 INFO [SimpleAsyncTaskExecutor-6] [execute] starting step: wait:33
2021-07-06 17:24:14.873 INFO [SimpleAsyncTaskExecutor-13] [execute] starting step: wait:0
2021-07-06 17:24:14.875 INFO [SimpleAsyncTaskExecutor-15] [execute] starting step: wait:25
2021-07-06 17:24:14.875 INFO [SimpleAsyncTaskExecutor-14] [execute] starting step: wait:13
2021-07-06 17:24:14.882 INFO [SimpleAsyncTaskExecutor-8] [execute] starting step: wait:6
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-3] [execute] Step: [wait:2] executed in 10s23ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-11] [execute] Step: [wait:27] executed in 10s18ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-5] [execute] Step: [wait:16] executed in 10s22ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-9] [execute] Step: [wait:3] executed in 10s19ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-12] [execute] Step: [wait:4] executed in 10s18ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-10] [execute] Step: [wait:34] executed in 10s19ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-7] [execute] Step: [wait:7] executed in 10s20ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-2] [execute] Step: [wait:11] executed in 10s24ms
2021-07-06 17:24:14.885 INFO [SimpleAsyncTaskExecutor-1] [execute] Step: [wait:29] executed in 10s25ms
2021-07-06 17:24:14.886 DEBUG [SimpleAsyncTaskExecutor-3] [afterAccess] Returning from throttle at concurrency count 14
2021-07-06 17:24:14.887 DEBUG [SimpleAsyncTaskExecutor-12] [afterAccess] Returning from throttle at concurrency count 13
2021-07-06 17:24:14.887 DEBUG [SimpleAsyncTaskExecutor-9] [afterAccess] Returning from throttle at concurrency count 12
2021-07-06 17:24:14.887 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 12
2021-07-06 17:24:14.888 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 13
2021-07-06 17:24:14.888 DEBUG [SimpleAsyncTaskExecutor-10] [afterAccess] Returning from throttle at concurrency count 13
2021-07-06 17:24:14.888 DEBUG [SimpleAsyncTaskExecutor-5] [afterAccess] Returning from throttle at concurrency count 12
2021-07-06 17:24:14.888 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 12
2021-07-06 17:24:14.889 DEBUG [SimpleAsyncTaskExecutor-7] [afterAccess] Returning from throttle at concurrency count 12
2021-07-06 17:24:14.889 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 12
2021-07-06 17:24:14.889 DEBUG [SimpleAsyncTaskExecutor-2] [afterAccess] Returning from throttle at concurrency count 12
2021-07-06 17:24:14.890 DEBUG [SimpleAsyncTaskExecutor-11] [afterAccess] Returning from throttle at concurrency count 11
2021-07-06 17:24:14.890 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 11
2021-07-06 17:24:14.890 DEBUG [SimpleAsyncTaskExecutor-1] [afterAccess] Returning from throttle at concurrency count 11
2021-07-06 17:24:14.890 INFO [SimpleAsyncTaskExecutor-4] [execute] Step: [wait:18] executed in 10s29ms
2021-07-06 17:24:14.890 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 11
2021-07-06 17:24:14.890 INFO [SimpleAsyncTaskExecutor-16] [execute] starting step: wait:30
2021-07-06 17:24:14.891 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 12
2021-07-06 17:24:14.892 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 13
2021-07-06 17:24:14.892 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 14
2021-07-06 17:24:14.892 INFO [SimpleAsyncTaskExecutor-17] [execute] starting step: wait:12
2021-07-06 17:24:14.892 DEBUG [main] [beforeAccess] Concurrency count 15 has reached limit 15 - blocking
2021-07-06 17:24:14.893 DEBUG [SimpleAsyncTaskExecutor-4] [afterAccess] Returning from throttle at concurrency count 14
2021-07-06 17:24:14.893 INFO [SimpleAsyncTaskExecutor-18] [execute] starting step: wait:28
2021-07-06 17:24:14.893 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 14
2021-07-06 17:24:14.894 DEBUG [main] [beforeAccess] Concurrency count 15 has reached limit 15 - blocking
2021-07-06 17:24:14.894 INFO [SimpleAsyncTaskExecutor-19] [execute] starting step: wait:24
2021-07-06 17:24:14.899 INFO [SimpleAsyncTaskExecutor-21] [execute] starting step: wait:23
2021-07-06 17:24:24.878 INFO [SimpleAsyncTaskExecutor-20] [execute] starting step: wait:1
2021-07-06 17:24:24.879 INFO [SimpleAsyncTaskExecutor-22] [execute] starting step: wait:32
2021-07-06 17:24:24.879 INFO [SimpleAsyncTaskExecutor-23] [execute] starting step: wait:15
2021-07-06 17:24:24.879 INFO [SimpleAsyncTaskExecutor-24] [execute] starting step: wait:10
2021-07-06 17:24:24.884 INFO [SimpleAsyncTaskExecutor-6] [execute] Step: [wait:33] executed in 20s19ms
2021-07-06 17:24:24.884 INFO [SimpleAsyncTaskExecutor-13] [execute] Step: [wait:0] executed in 20s17ms
2021-07-06 17:24:24.885 INFO [SimpleAsyncTaskExecutor-15] [execute] Step: [wait:25] executed in 20s17ms
2021-07-06 17:24:24.885 INFO [SimpleAsyncTaskExecutor-25] [execute] starting step: wait:17
2021-07-06 17:24:24.894 INFO [SimpleAsyncTaskExecutor-14] [execute] Step: [wait:13] executed in 20s26ms
2021-07-06 17:24:24.894 INFO [SimpleAsyncTaskExecutor-8] [execute] Step: [wait:6] executed in 20s29ms
2021-07-06 17:24:24.897 DEBUG [SimpleAsyncTaskExecutor-6] [afterAccess] Returning from throttle at concurrency count 14
2021-07-06 17:24:24.898 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 14
2021-07-06 17:24:24.898 DEBUG [SimpleAsyncTaskExecutor-13] [afterAccess] Returning from throttle at concurrency count 14
2021-07-06 17:24:24.899 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 14
2021-07-06 17:24:24.899 INFO [SimpleAsyncTaskExecutor-16] [execute] Step: [wait:30] executed in 10s12ms
2021-07-06 17:24:24.899 DEBUG [SimpleAsyncTaskExecutor-15] [afterAccess] Returning from throttle at concurrency count 14
2021-07-06 17:24:24.899 DEBUG [main] [beforeAccess] Entering throttle at concurrency count 14
2021-07-06 17:24:24.900 INFO [SimpleAsyncTaskExecutor-17] [execute] Step: [wait:12] executed in 10s12ms
Upvotes: 2
Views: 3324
Answers (1)
Mahmoud Ben Hassine
Reputation: 31600
Indeed I do not reproduce with your code sample. Here is an example that reproduces the error: github.com/AlexandreChi/spring-batch-lab/tree/main/issues/…. The only difference with your code sample is the annotation SpringBootApplication instead of Configuration.
So I conclude this is something related to the auto-configuration by boot.
I think I am getting close, associating EnableAutoConfiguration and implementation 'com.h2database:h2:1.4.198' is generating the issue. It seems it creates an autowired datasource which has a limited number of simultaneous connections
Indeed, in the logs I see:
DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
which is the default value of the max pool size using HikariCP. This means the 15 threads could not acquire more than 10 database connections, and hence only 10 of them could be running in parallel at a time.
Increasing the max pool size to 15 by adding the following property fixes the issue:
spring.datasource.hikari.maximum-pool-size=15
I updated the repo accordingly so you can check the result.
Upvotes: 2
Related Questions
- Unable to limit the parallelism using ThreadPoolExecutor with Spring Batch
- How to set up multi-threading in Spring Batch?
- Spring batch multithreading has a default limit of 10 implicitly?
- Spring Batch limits number of concurrent threads to 10
- Spring boot batch - ThreadPoolTaskExecutor not processing all the threads
- How to make spring batch step execution parallel with configurable thread count?
- Spring Batch Multiple Threads
- How to control the number of parallel Spring Batch jobs
- Multithreading in Spring Batch
- Spring batch- Parallel processing