Spring Batch занимает одну минуту до завершения - PullRequest
Новая
       82

Spring Batch занимает одну минуту до завершения

0 голосов
/ 28 мая 2020

После завершения моего задания Spring Batch до запуска обработчика выключения требуется около одной минуты. Поскольку я все еще учусь пользоваться фреймворком, я совершенно уверен, что что-то неправильно сконфигурировал.

Моя работа и шаг просты: читать данные из базы данных и записывать их обратно в другую таблицу. 

@Bean
public Job importUserJob(Step step1)
{
return jobBuilderFactory.get("importUserJob")
                        .incrementer(new RunIdIncrementer())
                        .flow(step1)
                        .end()
                        .build();
}

@Bean
public Step step1(JdbcCursorItemReader<User> reader, SaveAllRepositoryItemWriter<User> writer)
{
return stepBuilderFactory.get("step1")
                         .<User, User> chunk(1000)
                         .reader(reader)
                         .writer(writer)
                         .build();
}

SaveAllRepositoryItemWriter - это упрощенная версия RepositoryItemWriter, которая принимает CrudRepository и вызывает CrudRepository.saveAll() в его write() -методе (см. Ниже).

Последние строки вывод журнала выглядит следующим образом: 

2020-05-28 10:53:57.213  INFO 5964 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=importUserJob]] launched with the following parameters: [{run.id=23}]
2020-05-28 10:53:57.264  INFO 5964 --- [           main] o.s.batch.core.job.SimpleStepHandler     : Executing step: [step1]
2020-05-28 10:53:57.643  WARN 5964 --- [           main] c.n.d.SaveAllRepositoryItemWriter        : Writing finished
2020-05-28 10:53:57.664  INFO 5964 --- [           main] o.s.batch.core.step.AbstractStep         : Step: [step1] executed in 400ms
2020-05-28 10:53:57.676  INFO 5964 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=importUserJob]] completed with the following parameters: [{run.id=23}] and the following status: [COMPLETED] in 441ms
2020-05-28 10:54:57.002  INFO 5964 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-05-28 10:54:57.004  INFO 5964 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2020-05-28 10:54:57.004  INFO 5964 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-05-28 10:54:57.006  INFO 5964 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

Я добавил вывод журнала Writing finished, чтобы убедиться, что Writer действительно записал данные, как я видел здесь , что это может быть проблема.

Если я не предоставил достаточно информации, я рад предоставить дополнительную информацию. 

public class SaveAllRepositoryItemWriter<T> implements ItemWriter<T>, InitializingBean
{
  private CrudRepository<T, ?> repository;
  protected static final Log logger = LogFactory.getLog(SaveAllRepositoryItemWriter.class);

  public void setRepository(CrudRepository<T, ?> repository)
  {
    this.repository = repository;
  }

  /**
   * Check mandatory properties - there must be a repository.
   */
  @Override
  public void afterPropertiesSet() throws Exception
  {
    Assert.state(repository != null, "A CrudRepository implementation is required");
  }

  @Override
  public void write(List<? extends T> items) throws Exception
  {
    this.repository.saveAll(items);
    logger.warn("Writing finished");
  }
}

Журнал отладки: 

2020-05-28 11:27:15.541 DEBUG 9984 --- [           main] o.s.batch.core.step.AbstractStep         : Step execution complete: StepExecution: id=25, version=3, name=step1, status=COMPLETED, exitStatus=COMPLETED, readCount=0, filterCount=0, writeCount=0 readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=1, rollbackCount=0
2020-05-28 11:27:15.541 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-05-28 11:27:15.541 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1002762002<open>)] for JPA transaction
2020-05-28 11:27:15.541 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@50448409]
2020-05-28 11:27:15.541 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
2020-05-28 11:27:15.541 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [UPDATE SPRING_BATCH.BATCH_JOB_EXECUTION_CONTEXT SET SHORT_CONTEXT = ?, SERIALIZED_CONTEXT = ? WHERE JOB_EXECUTION_ID = ?]
2020-05-28 11:27:15.547 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2020-05-28 11:27:15.547 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1002762002<open>)]
2020-05-28 11:27:15.548 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1002762002<open>)] after transaction
2020-05-28 11:27:15.548 DEBUG 9984 --- [           main] o.s.b.core.job.flow.support.SimpleFlow   : Completed state=importUserJob.step1 with status=COMPLETED
2020-05-28 11:27:15.548 DEBUG 9984 --- [           main] o.s.b.core.job.flow.support.SimpleFlow   : Handling state=importUserJob.COMPLETED
2020-05-28 11:27:15.548 DEBUG 9984 --- [           main] o.s.b.core.job.flow.support.SimpleFlow   : Completed state=importUserJob.COMPLETED with status=COMPLETED
2020-05-28 11:27:15.549 DEBUG 9984 --- [           main] o.s.batch.core.job.AbstractJob           : Job execution complete: JobExecution: id=25, version=1, startTime=Thu May 28 09:27:15 UTC 2020, endTime=null, lastUpdated=Thu May 28 09:27:15 UTC 2020, status=COMPLETED, exitStatus=exitCode=COMPLETED;exitDescription=, job=[JobInstance: id=25, version=0, Job=[importUserJob]], jobParameters=[{run.id=25}]
2020-05-28 11:27:15.550 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.update]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-05-28 11:27:15.550 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(708004780<open>)] for JPA transaction
2020-05-28 11:27:15.550 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@470d183]
2020-05-28 11:27:15.550 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2020-05-28 11:27:15.550 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT VERSION FROM SPRING_BATCH.BATCH_JOB_EXECUTION WHERE JOB_EXECUTION_ID=?]
2020-05-28 11:27:15.551 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2020-05-28 11:27:15.551 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT COUNT(*) FROM SPRING_BATCH.BATCH_JOB_EXECUTION WHERE JOB_EXECUTION_ID = ?]
2020-05-28 11:27:15.555 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
2020-05-28 11:27:15.555 DEBUG 9984 --- [           main] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [UPDATE SPRING_BATCH.BATCH_JOB_EXECUTION set START_TIME = ?, END_TIME = ?,  STATUS = ?, EXIT_CODE = ?, EXIT_MESSAGE = ?, VERSION = ?, CREATE_TIME = ?, LAST_UPDATED = ? where JOB_EXECUTION_ID = ? and VERSION = ?]
2020-05-28 11:27:15.556 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2020-05-28 11:27:15.556 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(708004780<open>)]
2020-05-28 11:27:15.557 DEBUG 9984 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(708004780<open>)] after transaction
2020-05-28 11:27:15.557  INFO 9984 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=importUserJob]] completed with the following parameters: [{run.id=25}] and the following status: [COMPLETED] in 247ms
2020-05-28 11:28:15.069 DEBUG 9984 --- [extShutdownHook] s.c.a.AnnotationConfigApplicationContext : Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@13e39c73, started on Thu May 28 09:27:12 UTC 2020
2020-05-28 11:28:15.072  INFO 9984 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-05-28 11:28:15.073  INFO 9984 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2020-05-28 11:28:15.074  INFO 9984 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-05-28 11:28:15.075  INFO 9984 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

Информация- Журнал содержит около 100000 элементов: 

2020-05-28 15:01:58.230  INFO 8172 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=importUserJob]] launched with the following parameters: [{run.id=5}]
2020-05-28 15:01:58.275  INFO 8172 --- [           main] o.s.batch.core.job.SimpleStepHandler     : Executing step: [step1]
2020-05-28 15:02:03.640  INFO 8172 --- [           main] c.n.d.SaveAllRepositoryItemWriter        : Written 10000 items.
2020-05-28 15:02:13.757  INFO 8172 --- [           main] c.n.d.SaveAllRepositoryItemWriter        : Written 10000 items.
...
2020-05-28 15:04:24.750  INFO 8172 --- [           main] c.n.d.SaveAllRepositoryItemWriter        : Written 8512 items.
2020-05-28 15:04:29.041  INFO 8172 --- [           main] o.s.batch.core.step.AbstractStep         : Step: [step1] executed in 2m30s766ms
2020-05-28 15:04:29.065  INFO 8172 --- [           main] o.s.b.c.l.support.SimpleJobLauncher      : Job: [FlowJob: [name=importUserJob]] completed with the following parameters: [{run.id=5}] and the following status: [COMPLETED] in 2m30s816ms
2020-05-28 15:04:29.068  INFO 8172 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-05-28 15:04:29.070  INFO 8172 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2020-05-28 15:04:29.071  INFO 8172 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-05-28 15:04:29.073  INFO 8172 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

application.properties 

spring.datasource.url=jdbc:postgresql://some_ip:5432/some_db
spring.datasource.username=user
spring.datasource.password=pw

spring.jpa.properties.hibernate.dialect = org.hibernate.spatial.dialect.postgis.PostgisDialect
spring.jooq.sql-dialect=Postgres

spring.flyway.schemas = my_schema
spring.flyway.default-schema = my_schema

# Write metadata into own schema
# See https://stackoverflow.com/a/62057739/2021763 for an explanation
spring.batch.initialize-schema=always
spring.batch.table-prefix=SPRING_BATCH.BATCH_
spring.batch.schema=classpath:db/create_spring_batch_tables.sql

Зависимости в pom.xml (опущенная область тестирования) 

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-batch</artifactId>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-data-jpa</artifactId>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-data-jdbc</artifactId>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-jooq</artifactId>
</dependency>
<dependency>
    <groupId>org.flywaydb</groupId>
    <artifactId>flyway-core</artifactId>
</dependency>
<dependency>
    <groupId>org.hibernate</groupId>
    <artifactId>hibernate-spatial</artifactId>
</dependency>
<dependency>
    <groupId>org.postgresql</groupId>
    <artifactId>postgresql</artifactId>
    <scope>runtime</scope>
</dependency>
...