I wonder what causes in Spring batch job to have like 2 second delays between executing steps:
2024-12-06 15:42:18,975 INFO o.s.b.a.b.JobLauncherApplicationRunner - Running default command line with: []
2024-12-06 15:42:20,476 INFO o.s.b.c.l.s.SimpleJobLauncher - Job: [SimpleJob: [name=annualReportJob]] launched with the following parameters: [{}]
2024-12-06 15:42:22,500 INFO o.s.b.c.j.SimpleStepHandler - Executing step: [reportStep]
2025-02-26 15:41:18,461 INFO o.s.b.c.l.s.SimpleJobLauncher - Job: [SimpleJob: [name=importUserJob]] launched with the following parameters: [{'filename':'{value=.\files\export.txt, type=class java.lang.String, identifying=true}'}]
2025-02-26 15:41:18,462 DEBUG o.s.b.c.j.AbstractJob - Job execution starting: JobExecution: id=1, version=0, startTime=null, endTime=null, lastUpdated=2025-02-26T15:41:18.395423200, status=STARTING, exitStatus=exitCode=UNKNOWN;exitDescription=, job=[JobInstance: id=1, version=0, Job=[importUserJob]], jobParameters=[{'filename':'{value=.\files\export.txt, type=class java.lang.String, identifying=true}'}]
2025-02-26 15:41:18,471 DEBUG i.m.c.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
2025-02-26 15:41:18,472 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.update]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:18,472 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(378898852<open>)] for JPA transaction
2025-02-26 15:41:18,472 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:18,472 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:18,980 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@113d760e]
2025-02-26 15:41:18,982 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL query
2025-02-26 15:41:18,982 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [SELECT VERSION
FROM BATCH_JOB_EXECUTION
WHERE JOB_EXECUTION_ID=?
]
2025-02-26 15:41:18,982 DEBUG o.s.j.d.DataSourceUtils - Fetching JDBC Connection from DataSource
2025-02-26 15:41:18,982 DEBUG o.s.j.d.SimpleDriverDataSource - Creating new JDBC Driver Connection to [jdbc:h2:mem:78f13706-5351-4e4d-b137-763ab5c449da;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false]
2025-02-26 15:41:18,987 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL query
2025-02-26 15:41:18,987 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [SELECT COUNT(*)
FROM BATCH_JOB_EXECUTION
WHERE JOB_EXECUTION_ID = ?
]
2025-02-26 15:41:18,989 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL update
2025-02-26 15:41:18,989 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [UPDATE BATCH_JOB_EXECUTION
SET START_TIME = ?, END_TIME = ?, STATUS = ?, EXIT_CODE = ?, EXIT_MESSAGE = ?, VERSION = ?, CREATE_TIME = ?, LAST_UPDATED = ?
WHERE JOB_EXECUTION_ID = ? AND VERSION = ?
]
2025-02-26 15:41:18,991 DEBUG o.s.o.j.JpaTransactionManager - Initiating transaction commit
2025-02-26 15:41:18,991 DEBUG o.s.o.j.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(378898852<open>)]
2025-02-26 15:41:18,991 DEBUG o.h.e.t.i.TransactionImpl - committing
2025-02-26 15:41:18,991 DEBUG o.s.o.j.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(378898852<open>)] after transaction
2025-02-26 15:41:19,013 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.getLastStepExecution]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:19,013 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(429243151<open>)] for JPA transaction
2025-02-26 15:41:19,013 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:19,013 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:19,484 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7aa33987]
2025-02-26 15:41:19,485 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL query
2025-02-26 15:41:19,485 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [SELECT SE.STEP_EXECUTION_ID, SE.STEP_NAME, SE.START_TIME, SE.END_TIME, SE.STATUS, SE.COMMIT_COUNT, SE.READ_COUNT, SE.FILTER_COUNT, SE.WRITE_COUNT, SE.EXIT_CODE, SE.EXIT_MESSAGE, SE.READ_SKIP_COUNT, SE.WRITE_SKIP_COUNT, SE.PROCESS_SKIP_COUNT, SE.ROLLBACK_COUNT, SE.LAST_UPDATED, SE.VERSION, SE.CREATE_TIME, JE.JOB_EXECUTION_ID, JE.START_TIME, JE.END_TIME, JE.STATUS, JE.EXIT_CODE, JE.EXIT_MESSAGE, JE.CREATE_TIME, JE.LAST_UPDATED, JE.VERSION
FROM BATCH_JOB_EXECUTION JE
JOIN BATCH_STEP_EXECUTION SE ON SE.JOB_EXECUTION_ID = JE.JOB_EXECUTION_ID
WHERE JE.JOB_INSTANCE_ID = ? AND SE.STEP_NAME = ?
ORDER BY SE.CREATE_TIME DESC, SE.STEP_EXECUTION_ID DESC
]
2025-02-26 15:41:19,485 DEBUG o.s.j.d.DataSourceUtils - Fetching JDBC Connection from DataSource
2025-02-26 15:41:19,485 DEBUG o.s.j.d.SimpleDriverDataSource - Creating new JDBC Driver Connection to [jdbc:h2:mem:78f13706-5351-4e4d-b137-763ab5c449da;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false]
2025-02-26 15:41:19,487 DEBUG o.s.o.j.JpaTransactionManager - Initiating transaction commit
2025-02-26 15:41:19,487 DEBUG o.s.o.j.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(429243151<open>)]
2025-02-26 15:41:19,487 DEBUG o.h.e.t.i.TransactionImpl - committing
2025-02-26 15:41:19,487 DEBUG o.s.o.j.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(429243151<open>)] after transaction
2025-02-26 15:41:19,508 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.getStepExecutionCount]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:19,509 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(1667005369<open>)] for JPA transaction
2025-02-26 15:41:19,509 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:19,509 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:19,958 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@1790b3a]
2025-02-26 15:41:19,958 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL query
2025-02-26 15:41:19,959 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [SELECT COUNT(*)
FROM BATCH_JOB_EXECUTION JE
JOIN BATCH_STEP_EXECUTION SE ON SE.JOB_EXECUTION_ID = JE.JOB_EXECUTION_ID
WHERE JE.JOB_INSTANCE_ID = ? AND SE.STEP_NAME = ?
]
2025-02-26 15:41:19,959 DEBUG o.s.j.d.DataSourceUtils - Fetching JDBC Connection from DataSource
2025-02-26 15:41:19,959 DEBUG o.s.j.d.SimpleDriverDataSource - Creating new JDBC Driver Connection to [jdbc:h2:mem:78f13706-5351-4e4d-b137-763ab5c449da;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false]
2025-02-26 15:41:19,959 DEBUG o.s.o.j.JpaTransactionManager - Initiating transaction commit
2025-02-26 15:41:19,959 DEBUG o.s.o.j.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(1667005369<open>)]
2025-02-26 15:41:19,959 DEBUG o.h.e.t.i.TransactionImpl - committing
2025-02-26 15:41:19,960 DEBUG o.s.o.j.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(1667005369<open>)] after transaction
2025-02-26 15:41:19,981 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.add]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:19,982 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(2011140161<open>)] for JPA transaction
2025-02-26 15:41:19,982 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:19,982 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:20,458 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@5c69310b]
2025-02-26 15:41:20,459 DEBUG o.s.j.d.DataSourceUtils - Fetching JDBC Connection from DataSource
2025-02-26 15:41:20,459 DEBUG o.s.j.d.SimpleDriverDataSource - Creating new JDBC Driver Connection to [jdbc:h2:mem:78f13706-5351-4e4d-b137-763ab5c449da;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false]
2025-02-26 15:41:20,459 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL update
2025-02-26 15:41:20,459 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [INSERT INTO BATCH_STEP_EXECUTION(STEP_EXECUTION_ID, VERSION, STEP_NAME, JOB_EXECUTION_ID, START_TIME, END_TIME, STATUS, COMMIT_COUNT, READ_COUNT, FILTER_COUNT, WRITE_COUNT, EXIT_CODE, EXIT_MESSAGE, READ_SKIP_COUNT, WRITE_SKIP_COUNT, PROCESS_SKIP_COUNT, ROLLBACK_COUNT, LAST_UPDATED, CREATE_TIME)
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
]
2025-02-26 15:41:20,460 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL update
2025-02-26 15:41:20,460 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [INSERT INTO BATCH_STEP_EXECUTION_CONTEXT (SHORT_CONTEXT, SERIALIZED_CONTEXT, STEP_EXECUTION_ID)
VALUES(?, ?, ?)
]
2025-02-26 15:41:20,460 DEBUG o.s.o.j.JpaTransactionManager - Initiating transaction commit
2025-02-26 15:41:20,460 DEBUG o.s.o.j.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(2011140161<open>)]
2025-02-26 15:41:20,460 DEBUG o.h.e.t.i.TransactionImpl - committing
2025-02-26 15:41:20,460 DEBUG o.s.o.j.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(2011140161<open>)] after transaction
2025-02-26 15:41:20,483 INFO o.s.b.c.j.SimpleStepHandler - Executing step: [step1]
2025-02-26 15:41:20,483 DEBUG o.s.b.c.s.AbstractStep - Executing: id=1
2025-02-26 15:41:20,486 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.update]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:20,486 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(753643455<open>)] for JPA transaction
2025-02-26 15:41:20,486 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:20,486 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:20,967 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@791439f3]
2025-02-26 15:41:20,968 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL update
2025-02-26 15:41:20,968 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [UPDATE BATCH_STEP_EXECUTION
SET START_TIME = ?, END_TIME = ?, STATUS = ?, COMMIT_COUNT = ?, READ_COUNT = ?, FILTER_COUNT = ?, WRITE_COUNT = ?, EXIT_CODE = ?, EXIT_MESSAGE = ?, VERSION = ?, READ_SKIP_COUNT = ?, PROCESS_SKIP_COUNT = ?, WRITE_SKIP_COUNT = ?, ROLLBACK_COUNT = ?, LAST_UPDATED = ?
WHERE STEP_EXECUTION_ID = ? AND VERSION = ?
]
2025-02-26 15:41:20,968 DEBUG o.s.j.d.DataSourceUtils - Fetching JDBC Connection from DataSource
2025-02-26 15:41:20,968 DEBUG o.s.j.d.SimpleDriverDataSource - Creating new JDBC Driver Connection to [jdbc:h2:mem:78f13706-5351-4e4d-b137-763ab5c449da;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false]
2025-02-26 15:41:20,969 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL query
2025-02-26 15:41:20,969 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [SELECT VERSION
FROM BATCH_JOB_EXECUTION
WHERE JOB_EXECUTION_ID=?
]
2025-02-26 15:41:20,970 DEBUG o.s.o.j.JpaTransactionManager - Initiating transaction commit
2025-02-26 15:41:20,970 DEBUG o.s.o.j.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(753643455<open>)]
2025-02-26 15:41:20,970 DEBUG o.h.e.t.i.TransactionImpl - committing
2025-02-26 15:41:20,970 DEBUG o.s.o.j.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(753643455<open>)] after transaction
2025-02-26 15:41:20,995 DEBUG o.s.b.c.s.StepScope - Creating object in scope=step, name=scopedTarget.reader
2025-02-26 15:41:20,996 DEBUG o.s.b.f.s.DefaultListableBeanFactory - Autowiring by type from bean name 'scopedTarget.reader' via factory method to bean named 'insuranceDb'
2025-02-26 15:41:21,000 DEBUG o.s.b.c.s.StepScope - Registered destruction callback in scope=step, name=scopedTarget.reader
2025-02-26 15:41:21,528 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:21,528 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(1976862814<open>)] for JPA transaction
2025-02-26 15:41:21,528 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:21,528 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:21,976 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@bb6095d]
2025-02-26 15:41:21,982 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL update
2025-02-26 15:41:21,982 DEBUG o.s.j.c.JdbcTemplate - Executing prepared SQL statement [UPDATE BATCH_STEP_EXECUTION_CONTEXT
SET SHORT_CONTEXT = ?, SERIALIZED_CONTEXT = ?
WHERE STEP_EXECUTION_ID = ?
]
2025-02-26 15:41:21,982 DEBUG o.s.j.d.DataSourceUtils - Fetching JDBC Connection from DataSource
2025-02-26 15:41:21,982 DEBUG o.s.j.d.SimpleDriverDataSource - Creating new JDBC Driver Connection to [jdbc:h2:mem:78f13706-5351-4e4d-b137-763ab5c449da;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false]
2025-02-26 15:41:21,982 DEBUG o.s.o.j.JpaTransactionManager - Initiating transaction commit
2025-02-26 15:41:21,982 DEBUG o.s.o.j.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(1976862814<open>)]
2025-02-26 15:41:21,982 DEBUG o.h.e.t.i.TransactionImpl - committing
2025-02-26 15:41:21,983 DEBUG o.s.o.j.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(1976862814<open>)] after transaction
2025-02-26 15:41:22,005 DEBUG o.s.b.r.s.RepeatTemplate - Starting repeat context.
2025-02-26 15:41:22,006 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=1
2025-02-26 15:41:22,006 DEBUG o.s.b.c.s.c.StepContextRepeatCallback - Preparing chunk execution for StepContext: org.springframework.batch.core.scope.context.StepContext@a6939d6
2025-02-26 15:41:22,007 DEBUG o.s.b.c.s.c.StepContextRepeatCallback - Chunk execution starting: queue size=0
2025-02-26 15:41:22,008 DEBUG o.s.o.j.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2025-02-26 15:41:22,008 DEBUG o.s.o.j.JpaTransactionManager - Opened new EntityManager [SessionImpl(943146127<open>)] for JPA transaction
2025-02-26 15:41:22,008 DEBUG o.h.e.t.i.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2025-02-26 15:41:22,008 DEBUG o.h.e.t.i.TransactionImpl - begin
2025-02-26 15:41:22,452 DEBUG o.s.o.j.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@25427f89]
2025-02-26 15:41:22,453 DEBUG o.s.b.r.s.RepeatTemplate - Starting repeat context.
2025-02-26 15:41:22,453 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=1
2025-02-26 15:41:22,456 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=2
2025-02-26 15:41:22,456 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=3
2025-02-26 15:41:22,456 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=4
2025-02-26 15:41:22,456 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=5
2025-02-26 15:41:22,457 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=6
2025-02-26 15:41:22,457 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=7
2025-02-26 15:41:22,457 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=8
2025-02-26 15:41:22,457 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=9
2025-02-26 15:41:22,457 DEBUG o.s.b.r.s.RepeatTemplate - Repeat operation about to start at count=10
2025-02-26 15:41:22,457 DEBUG o.s.b.r.s.RepeatTemplate - Repeat is complete according to policy and result value.
2025-02-26 15:41:22,458 DEBUG o.s.b.c.s.JobScope - Creating object in scope=job, name=scopedTarget.writer
2025-02-26 15:41:22,460 INFO c.s.i.b.a.l.LoanExportWriter - Create file: .\files\export.txt
enter code here
There are 4 meta-data related transactions between the time of starting the job and the execution of the first step (see log blocks delimited by "Creating new transaction.." and "Closing JPA EntityManager" ), which confirms my previous comment.
These 4 transactions seem to take 2 seconds indeed. I can't tell if this is "so slow" or not, probably it is, in which case the startup process should be reviewed for possible enhancements.
BTW, we introduced a Resourceless job repository in version 5.2, which does not interact with any datasource (not even in memory), and which is faster than any other persistent or in-memory job repository implementation.