Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ThreadPoolaskExecutor blocks endless #4316

Closed
MelleD opened this issue Feb 27, 2023 · 6 comments
Closed

ThreadPoolaskExecutor blocks endless #4316

MelleD opened this issue Feb 27, 2023 · 6 comments
Labels
status: declined Features that we don't intend to implement or Bug reports that are invalid or missing enough details

Comments

@MelleD
Copy link

MelleD commented Feb 27, 2023

Based on the post here, which problem I can still reproduce by clicking in the browser several times.

But unfortunately I still don't quite understand the reason for the endless blocking.

On the tip of @fmbenhassine I also made the JobExecutor asynchron not only the steps

   @Bean
   public JobLauncher jobLauncher( final JobRepository jobRepository, final ThreadPoolTaskExecutor jobExecutor ) throws Exception {
      final SimpleJobLauncher jobLauncher = new SimpleJobLauncher();
      jobLauncher.setJobRepository( jobRepository );
      jobLauncher.setTaskExecutor( jobExecutor );
      jobLauncher.afterPropertiesSet();
      return jobLauncher;
   }

   @Bean
   public ThreadPoolTaskExecutor jobExecutor() {
      final ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
      executor.setCorePoolSize( 4 );
      executor.setMaxPoolSize( 25 );
      executor.setThreadNamePrefix( "jobExecutor-" );
      executor.initialize();
      return executor;
   }

But same result on some time the Threads are blocked and I see no ouput.

The third try was without REST Api, just on Application startup.

@Component
public class JobRunner implements ApplicationRunner {

   @Autowired
   private JobLauncher jobLauncher;

   @Autowired
   private Job job;

   public static JobParameters createJobParameters() {
      return new JobParametersBuilder()
            .addLong( "lastModifiedAt", Instant.now().toEpochMilli() )
            .toJobParameters();
   }

   @Override
   public void run( final ApplicationArguments args ) {
      IntStream.range( 0, 10 ).forEach( i -> {
         try {
            System.out.println( "Start new job" );
            jobLauncher.run( job, createJobParameters() );
            Thread.sleep( 500 );
         } catch ( final Exception e ) {
            e.printStackTrace();
         }

      } );

   }
}

But also blocked.

Maybe someone has a good hint for me and generally a few good tips for ThreadPoolTaskExecutor settings

Minimal Complete Reproducible example
For Problem 1 without asynchron job executor.
(https://github.com/MelleD/spring-batch-example)

@MelleD MelleD added status: waiting-for-triage Issues that we did not analyse yet type: bug labels Feb 27, 2023
@fmbenhassine fmbenhassine added in: core has: minimal-example Bug reports that provide a minimal complete reproducible example and removed status: waiting-for-triage Issues that we did not analyse yet labels Feb 27, 2023
@fmbenhassine
Copy link
Contributor

Thank you for opening this issue. I will plan the work on this for 5.0.2. As mentioned in SO, I think the issue is with the default throttle limit value of the TaskExecutorRepeatTemplate which is 4, being equal to the core pool size in the sample you shared. I remember things were working as expected when I tried your example with a core pool size >= 5, but I will re-check.

BTW, we acknowledge this is confusing, that's why that throttle limit is deprecated for removal (#2218) and the concurrency model will be reviewed in #3950.

@MelleD
Copy link
Author

MelleD commented Apr 24, 2023

@fmbenhassine thanks for update

@fmbenhassine fmbenhassine added this to the 5.0.2 milestone Apr 24, 2023
@fmbenhassine
Copy link
Contributor

Hi @MelleD ,

When I try your sample with the JobRunner shared above and a corePoolSize of 4 (ie without changing the config), then I realize that all jobs complete successfully, but the app is still running due to the ThreadPoolTaskExecutor being running. When I shut it down after the the Spring Boot app runs, the JVM exits as expected. Here is the change I made:

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.ConfigurableApplicationContext;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;

@SpringBootApplication
public class SpringBatchExampleApplication {

	public static void main(String[] args) {
		ConfigurableApplicationContext applicationContext = SpringApplication.run(SpringBatchExampleApplication.class, args);

		ThreadPoolTaskExecutor taskExecutor = applicationContext.getBean(ThreadPoolTaskExecutor.class);
		taskExecutor.shutdown();
	}

}

And here is the full log:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.7.8)

2023-05-11 14:18:59.494  INFO 75598 --- [           main] c.e.s.b.SpringBatchExampleApplication    : Starting SpringBatchExampleApplication using Java 17 on mbenhassine.dev with PID 75598 (/tmp/spring-batch-example-main/target/classes started by mbenhassine in /tmp/spring-batch-example-main)
2023-05-11 14:18:59.496  INFO 75598 --- [           main] c.e.s.b.SpringBatchExampleApplication    : No active profile set, falling back to 1 default profile: "default"
2023-05-11 14:18:59.976  WARN 75598 --- [           main] o.s.b.c.l.AbstractListenerFactoryBean    : org.springframework.batch.item.ItemProcessor is an interface. The implementing class will not be queried for annotation based listener configurations. If using @StepScope on a @Bean method, be sure to return the implementing class so listener annotations can be used.
2023-05-11 14:18:59.989  WARN 75598 --- [           main] o.s.b.c.l.AbstractListenerFactoryBean    : org.springframework.batch.item.ItemProcessor is an interface. The implementing class will not be queried for annotation based listener configurations. If using @StepScope on a @Bean method, be sure to return the implementing class so listener annotations can be used.
2023-05-11 14:18:59.990  WARN 75598 --- [           main] o.s.b.c.l.AbstractListenerFactoryBean    : org.springframework.batch.item.ItemProcessor is an interface. The implementing class will not be queried for annotation based listener configurations. If using @StepScope on a @Bean method, be sure to return the implementing class so listener annotations can be used.
2023-05-11 14:18:59.992  WARN 75598 --- [           main] o.s.b.c.l.AbstractListenerFactoryBean    : org.springframework.batch.item.ItemProcessor is an interface. The implementing class will not be queried for annotation based listener configurations. If using @StepScope on a @Bean method, be sure to return the implementing class so listener annotations can be used.
2023-05-11 14:19:00.011  INFO 75598 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2023-05-11 14:19:00.173  INFO 75598 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2023-05-11 14:19:00.295  INFO 75598 --- [           main] o.s.b.c.r.s.JobRepositoryFactoryBean     : No database type set, using meta data indicating: H2
2023-05-11 14:19:00.403  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : No TaskExecutor has been set, defaulting to synchronous executor.
2023-05-11 14:19:00.465  INFO 75598 --- [           main] c.e.s.b.SpringBatchExampleApplication    : Started SpringBatchExampleApplication in 1.227 seconds (JVM running for 1.61)
Start new job
2023-05-11 14:19:00.505  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807540467}]
2023-05-11 14:19:00.534  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
2023-05-11 14:19:00.534  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW3 sleeps for 4152
Flow Reader FLOW4 sleeps for 4152
FlowItemProcessor FLOW3 sleeps for 4152
FlowItemProcessor FLOW4 sleeps for 4152
Flow Writer finish FLOW4
Flow Writer finish FLOW3
Flow Reader FLOW4 sleeps for 4152
Flow Reader FLOW3 sleeps for 4152
2023-05-11 14:19:13.027  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 12s493ms
2023-05-11 14:19:13.027  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 12s493ms
2023-05-11 14:19:13.030  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
2023-05-11 14:19:13.030  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
FlowItemProcessor FLOW1 sleeps for 4152
FlowItemProcessor FLOW2 sleeps for 4152
Flow Writer finish FLOW2
Flow Writer finish FLOW1
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:19:25.500  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 12s470ms
2023-05-11 14:19:25.500  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 12s470ms
2023-05-11 14:19:25.504  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807540467}] and the following status: [COMPLETED] in 24s984ms
Start new job
2023-05-11 14:19:26.008  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807566005}]
2023-05-11 14:19:26.011  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
2023-05-11 14:19:26.012  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
Flow Reader FLOW4 sleeps for 4152
Flow Reader FLOW3 sleeps for 4152
2023-05-11 14:19:30.169  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s158ms
2023-05-11 14:19:30.169  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s157ms
2023-05-11 14:19:30.172  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:19:30.173  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:19:34.329  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s156ms
2023-05-11 14:19:34.329  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s157ms
2023-05-11 14:19:34.331  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807566005}] and the following status: [COMPLETED] in 8s322ms
Start new job
2023-05-11 14:19:34.836  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807574832}]
2023-05-11 14:19:34.839  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
2023-05-11 14:19:34.840  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW3 sleeps for 4152
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:19:38.995  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s155ms
2023-05-11 14:19:38.995  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s156ms
2023-05-11 14:19:38.997  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:19:38.997  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:19:43.155  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s158ms
2023-05-11 14:19:43.155  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s158ms
2023-05-11 14:19:43.156  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807574832}] and the following status: [COMPLETED] in 8s320ms
Start new job
2023-05-11 14:19:43.661  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807583658}]
2023-05-11 14:19:43.662  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:19:43.663  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
Flow Reader FLOW3 sleeps for 4152
2023-05-11 14:19:47.821  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s158ms
2023-05-11 14:19:47.822  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s158ms
2023-05-11 14:19:47.823  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:19:47.824  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:19:51.982  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s158ms
2023-05-11 14:19:51.982  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s159ms
2023-05-11 14:19:51.984  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807583658}] and the following status: [COMPLETED] in 8s322ms
Start new job
2023-05-11 14:19:52.490  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807592488}]
2023-05-11 14:19:52.492  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
Flow Reader FLOW3 sleeps for 4152
2023-05-11 14:19:52.493  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:19:56.646  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s154ms
2023-05-11 14:19:56.647  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s154ms
2023-05-11 14:19:56.648  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
Flow Reader FLOW2 sleeps for 4152
2023-05-11 14:19:56.649  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:20:00.805  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s157ms
2023-05-11 14:20:00.805  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s156ms
2023-05-11 14:20:00.807  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807592488}] and the following status: [COMPLETED] in 8s316ms
Start new job
2023-05-11 14:20:01.309  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807601307}]
2023-05-11 14:20:01.310  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:20:01.311  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
Flow Reader FLOW3 sleeps for 4152
2023-05-11 14:20:05.468  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s158ms
2023-05-11 14:20:05.469  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s158ms
2023-05-11 14:20:05.471  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
2023-05-11 14:20:05.471  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
Flow Reader FLOW1 sleeps for 4152
Flow Reader FLOW2 sleeps for 4152
2023-05-11 14:20:09.626  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s155ms
2023-05-11 14:20:09.626  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s155ms
2023-05-11 14:20:09.627  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807601307}] and the following status: [COMPLETED] in 8s318ms
Start new job
2023-05-11 14:20:10.130  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807610128}]
2023-05-11 14:20:10.132  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
2023-05-11 14:20:10.133  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW3 sleeps for 4152
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:20:14.287  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s154ms
2023-05-11 14:20:14.287  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s155ms
2023-05-11 14:20:14.289  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:20:14.289  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW1 sleeps for 4152
Flow Reader FLOW2 sleeps for 4152
2023-05-11 14:20:18.444  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s155ms
2023-05-11 14:20:18.444  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s155ms
2023-05-11 14:20:18.445  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807610128}] and the following status: [COMPLETED] in 8s315ms
Start new job
2023-05-11 14:20:18.949  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807618947}]
2023-05-11 14:20:18.951  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:20:18.951  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
Flow Reader FLOW3 sleeps for 4152
2023-05-11 14:20:23.110  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s159ms
2023-05-11 14:20:23.110  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s159ms
2023-05-11 14:20:23.112  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:20:23.112  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:20:27.268  INFO 75598 --- [bTaskExecutor-2] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s156ms
2023-05-11 14:20:27.268  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s156ms
2023-05-11 14:20:27.270  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807618947}] and the following status: [COMPLETED] in 8s320ms
Start new job
2023-05-11 14:20:27.772  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807627770}]
2023-05-11 14:20:27.774  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
2023-05-11 14:20:27.774  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW3 sleeps for 4152
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:20:31.929  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s155ms
2023-05-11 14:20:31.929  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s155ms
2023-05-11 14:20:31.930  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:20:31.930  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW2 sleeps for 4152
Flow Reader FLOW1 sleeps for 4152
2023-05-11 14:20:36.088  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s157ms
2023-05-11 14:20:36.088  INFO 75598 --- [bTaskExecutor-3] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s157ms
2023-05-11 14:20:36.089  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807627770}] and the following status: [COMPLETED] in 8s317ms
Start new job
2023-05-11 14:20:36.594  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] launched with the following parameters: [{lastModifiedAt=1683807636591}]
2023-05-11 14:20:36.595  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW3]
2023-05-11 14:20:36.596  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW4]
Flow Reader FLOW3 sleeps for 4152
Flow Reader FLOW4 sleeps for 4152
2023-05-11 14:20:40.753  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW3] executed in 4s158ms
2023-05-11 14:20:40.753  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW4] executed in 4s157ms
2023-05-11 14:20:40.754  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW2]
2023-05-11 14:20:40.754  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.job.SimpleStepHandler     : Executing step: [FLOW1]
Flow Reader FLOW1 sleeps for 4152
Flow Reader FLOW2 sleeps for 4152
2023-05-11 14:20:44.912  INFO 75598 --- [bTaskExecutor-1] o.s.batch.core.step.AbstractStep         : Step: [FLOW1] executed in 4s158ms
2023-05-11 14:20:44.912  INFO 75598 --- [bTaskExecutor-4] o.s.batch.core.step.AbstractStep         : Step: [FLOW2] executed in 4s158ms
2023-05-11 14:20:44.914  INFO 75598 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=JOB]] completed with the following parameters: [{lastModifiedAt=1683807636591}] and the following status: [COMPLETED] in 8s319ms
2023-05-11 14:20:45.418  INFO 75598 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2023-05-11 14:20:45.420  INFO 75598 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

I attach the zip of the minimal complete example (I just removed the web bits and used your JobRunner).

ThreadPoolaskExecutor blocks endless

So as I mentioned in SO, the ThreadPoolaskExecutor does not "blocks endless", it just needs to be shutdown after all jobs are finished (which is the case according to the logs, meaning the 4 parallel flows of each job are executed correctly with the given thread pool executor with a core pool size of 4).

Looking forward to your feedback.


gh-4316.zip

@fmbenhassine fmbenhassine added the status: waiting-for-reporter Issues for which we are waiting for feedback from the reporter label May 11, 2023
@MelleD
Copy link
Author

MelleD commented May 11, 2023

Thank you for your detailed answer, but I'm not sure if I understood it correctly. The ThreadPoolExecutor is normally only terminated when the server is stopped. That's why I don't quite understand what the solution is, because normally the ThreadPoolExecutor lives during the whole lifecycle.

@fmbenhassine
Copy link
Contributor

Yes, in a webapp that runs 24/7 there is no need to shut it down, it will be shutdown automatically when the server stops. The sample you shared initially is a webapp, and after all jobs submitted through the web controller are finished, the task executor will wait for other jobs to be submitted as long as the webapp is running. It does not block endless, it is there waiting for next jobs to run. To me there is no problem and this is no issue.

The only doubt you raised in SO is about the size of the core pool size:

If I currently try to use a ThreadPoolExecutor with a core size of 4, the job blocks forever and never completes.
As soon as I set the size to 5 everything works fine.

That's what I tried to clarify through the sample: things works as expected even with a core pool size of 4.

The other point about the thread pool lifecycle is a no issue. Hopefully this clarifies things further.

@fmbenhassine
Copy link
Contributor

I am closing this ticket as I believe it is a no issue as explained previously, but you can add a comment if you need more help on the case.

@fmbenhassine fmbenhassine closed this as not planned Won't fix, can't repro, duplicate, stale May 16, 2023
@fmbenhassine fmbenhassine added status: declined Features that we don't intend to implement or Bug reports that are invalid or missing enough details and removed status: waiting-for-reporter Issues for which we are waiting for feedback from the reporter type: bug in: core has: minimal-example Bug reports that provide a minimal complete reproducible example labels May 16, 2023
@fmbenhassine fmbenhassine removed this from the 5.0.2 milestone May 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: declined Features that we don't intend to implement or Bug reports that are invalid or missing enough details
Projects
None yet
Development

No branches or pull requests

2 participants