After the completion of my Spring Batch job, it takes about one minute till the shutdown hook is launched. As I am still learning how to use the framework, I am quite sure I misconfigured something.
My job and step is straightforward: read data from a database and write it back in another table.
@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 is a simplified version of RepositoryItemWriter, which takes a CrudRepository and calls CrudRepository.saveAll() in it's write()-method (see below).
The last lines of the log output is as follows:
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.
I added the log output Writing finished to ensure that the Writer has actually written the data, as I have seen here that it might be a problem.
If I did not provide enough information, I am happy to provide more information.
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");
}
}
Debug Log:
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.
Info-Log with around 100'000 items:
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
Dependencies in the pom.xml (omitted test-scope)
<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>
