Taking quite a lot of time to launch a job's very first step.

[sk75067]

I have a job which has 1)clean-up steps and then 2) load steps in parallel... I'm trying to understand/figure out what and why is Spring/Srping-Batch consuming good amount of 30 minutes (16:32 - 17:04) before start executing the very first step. If someone know what's going on here or is it taking 30 minutes to load all those singletons? Thanks for your help.

Here is copy of the log trace:

2011-05-25 16:32:29.069 [ INFO] [main] org.springframework.beans.factory.support.DefaultL istableBeanFactory:414 => Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultL istableBeanFactory@8ceeea: defining beans [..... removed all the singletons to save space] ; root of factory hierarchy

2011-05-25 16:32:29.537 [ INFO] [main] org.springframework.batch.core.launch.support.Simp leJobLauncher:179 => No TaskExecutor has been set, defaulting to synchronous executor.
2011-05-25 16:32:29.537 [ INFO] [main] org.springframework.batch.core.launch.support.Simp leJobLauncher:179 => No TaskExecutor has been set, defaulting to
synchronous executor.

2011-05-25 17:04:03.839 [ INFO] [main] org.springframework.batch.core.launch.support.Simp leJobLauncher:118 => Job: [FlowJob: [name=jobLoadAllSources]] launched with the following parameters: [{job_run_date_time=1306357443570}]
2011-05-25 17:04:03.839 [ INFO] [main] org.springframework.batch.core.launch.support.Simp leJobLauncher:118 => Job: [FlowJob: [name=jobLoadAllSources]] launched with the following parameters: [{job_run_date_time=1306357443570}]
2011-05-25 17:04:03.945 [ INFO] [main] org.springframework.batch.core.job.SimpleStepHandl er:133 => Executing step: [jobLoadAllSources-stepSendEmailBegin]
2011-05-25 17:04:03.945 [ INFO] [main] org.springframework.batch.core.job.SimpleStepHandl er:133 => Executing step: [jobLoadAllSources-stepSendEmailBegin]
2011-05-25 17:04:04.002 [ INFO] [main] com.citigroup.cti.gto.gis.gssm.reporting.etl.tasks .TaskletCallUnixScriptToSendEmail:36 => Unix Script to send an e-mail: [Ljava.lang.String;@5879fd
2011-05-25 17:04:04.350 [ INFO] [main] com.citigroup.cti.gto.gis.gssm.reporting.etl.tasks .TaskletCallUnixScriptToSendEmail:47 => Send-Email Unix Script is complete and the return code is: 0
2011-05-25 17:04:04.873 [ INFO] [SimpleAsyncTaskExecutor-3] org.springframework.batch.core.job.SimpleStepHandl er:133 => Executing step: [flowTruncateHosts-stepTruncate]
2011-05-25 17:04:04.873 [ INFO] [SimpleAsyncTaskExecutor-3] org.springframework.batch.core.job.SimpleStepHandl er:133 => Executing step: [flowTruncateHosts-stepTruncate]
2011-05-25 17:04:04.904 [ INFO] [SimpleAsyncTaskExecutor-7] org.springframework.batch.core.job.SimpleStepHandl er:133 => Executing step: [flowTruncateClosedAssessment-stepTruncate]

[bwawok]

So it is likely trying to put junk in your spring batch tables about the job state. My guess is either
a) You have 600 jobs all trying to start at the same time, and they are fighting for the tables (not likley)
b) You have oracle, and are running on linux, and dealing with the "linux slow to get oracle connection" problem (more likley)


The tip is.. RIGHT before the job launched log statement.. is

 jobExecution = jobRepository.createJobExecution(job.getName(), jobParameters);

This will both open a new DB connection, and try to put spring batchy stuff in the database.

Do some thread dumps during the pause to confirm threads are doing stuff with the database.. and find out exactly what.

[sk75067]

After doing further debugging, narrow it down to the line of code which is taking 30 minutes to all the steps/xmls to load the context. Just wondering how to improve the performance of loading the spring-context.

context = new ClassPathXmlApplicationContext(jobPath); // line of code from CommandLineJobRunner.java

[Dave Syer]

That doesn't really help without a thread dump. If you are using Java 6 you can get one with jstack.

[sk75067]

Thanks for your inputs. I'm trying to understand the thread dump but couldn't. Dave, Can point me to the place in the attached log file where you see the potential issue which is causing above issue?

[Dave Syer]

There's nothing unusual or alarming there. The bean factory is initializing which is complete normal - it's not normal for it to take more than a few seconds at most. Why it is taking so long remains a mystery. If you enable INFO logging you should see a count of the bean definitions in each ApplicationContext as it starts up. There might be a clue there.