Processes executed by this system are often batch-oriented, which is why the system contains a dedicated service that uses the Spring Batch framework to execute these long-running jobs.<\/p>\n\n\n\n
Of course it then becomes important to be able to observe these executions: how long do the jobs take to run, are there failures, what logging is associated with these jobs, etc.
Spring Boot and Batch provide some metrics out of the box, but to really make the most effective use of the frameworks you need some tuning and some understanding of the components involved. In this post I want to showcase some things that we\u2019ve done to optimize the observability of our Spring Batch jobs.<\/p>\n\n\n\n
We are using Datadog, but these tips apply to other observability tools as well, esp. those that combine metrics with logging.<\/p>\n\n\n\n
First things first: ensuring consistent tag names<\/h1>\n\n\n\n
Spring Batch provides metrics for components at different levels: jobs, steps, chunks and items. With version 4 of the frameworks, the tags used in these different metrics to identify things like job names are unfortunately not consistent. Metrics for jobs have a \u201c Our team is still busy to complete the migration to Boot 3 and Batch 5. One of the reasons that this is far from trivial for us is that we\u2019re using a 3rd-party add-on called Lightmin<\/a>, which provides a nice Web UI for inspecting jobs and executions and also allows you to schedule these executions while storing the schedule in your database: functionality that\u2019s lacking in Spring Batch itself. In the process of doing this I discovered that Batch 5 also changed its metric tag names: for jobs it now uses \u201c To ensure that our metrics tags are consistent today with Batch 4 and will stay consistent when we update to Batch 5, I wrote some Micrometer meter filters:<\/p>\n\n\n This will cause some sane and consistent naming across the various batch metrics that we care about.<\/p>\n\n\n\n The real power of observability comes from being able to combine various types of information: metrics, logging and traces. With the above changes, it becomes very easy to create a dashboard that shows various graphs based on batch metrics which can all be filtered by job. It would be really nice if we could include log messages in that same dashboard that would also<\/em> respect the overall filtering on a job name.<\/p>\n\n\n\n To make that work, we need two things.<\/p>\n\n\n\n First of all, we obviously need to add the job name to all log messages that are produced in the context of a job execution. This is easiest to do by adding an MDC attribute using your own JobLauncher. You can see how to do just that in one of our old blogs<\/a>.<\/p>\n\n\n\n While working on this system, I basically copied the code from my own blog and patted myself on the back. This is what it looks like:<\/p>\n\n\n However, when I tested it I didn\u2019t see anything\u2026 <\/p>\n\n\n\n As it turns out, our system simply ignores the job launcher that you can configure if you override the createJobLauncher from a batch configurer parent class<\/a> because Lightmin has its own<\/em> configuration for creating launchers.<\/p>\n\n\n\n You can override that by defining two beans yourself, a scheduler configuration and a listener configuration. Here\u2019s the code for the scheduler, the listener version is basically the same:<\/p>\n\n\n I added a static method to our custom job launcher that we\u2019re calling in the above code:<\/p>\n\n\n As I already mentioned, we actually need to do two things to be able to allow our dashboard filtering to apply to logging as well. However, the value that\u2019s shown is different from the values that are used for our metrics. This is what shows up there:<\/p>\n\n\n\n As it turns out, Datadog only supports certain characters to be used in a tag value and replaces the rest with underscores. It also lowercases everything. Now we simply call that when adding the job name to the MDC and everything starts working exactly like we want it to.<\/p>\n\n\n\n We\u2019re ready to create our dashboard! name<\/code>\u201d tag, but the step- and chunk-related metrics refer to a \u201cjob.name<\/code>\u201d.
This makes it harder to build a dashboard where you can easily filter by job name using a template variable.<\/p>\n\n\n\nBatch 4 vs Batch 5<\/h2>\n\n\n\n
However, Lightmin isn\u2019t actively maintained anymore, and Batch 5 contains a ton of breaking changes. That means we have to effectively create a private fork and update everything ourselves.<\/p>\n\n\n\nspring.batch.job.name<\/code>\u201d, while in steps it uses \u201cspring.batch.step.job.name<\/code>\u201d to identify the job. The tag name for names of steps changed as well. So these tags are still inconsistent, but now in a different way \ud83e\udd79
It also seems that the documentation hasn’t been updated<\/a> to reflect these changes yet.<\/p>\n\n\n\nTaking Control<\/h2>\n\n\n\n
\n\/**\n* @see org.springframework.batch.core.observability.BatchJobObservation.JobLowCardinalityTags#JOB_NAME\n*\/\n@Bean\nMeterFilter jobJobNameTagRenamingMeterFilter() {\n String prefix = "spring.batch.job";\n boolean batchV5 = ClassUtils.isPresent("org.springframework.batch.core.observability.BatchJobObservation", null);\n String from = batchV5 ? prefix + ".name" : "name";\n return MeterFilter.renameTag(prefix, from, "job.name");\n}\n\n\n\/**\n* @see org.springframework.batch.core.observability.BatchStepObservation.StepLowCardinalityTags#JOB_NAME\n*\/\n@Bean @ConditionalOnClass(name = "org.springframework.batch.core.observability.BatchStepObservation")\nMeterFilter stepJobNameTagRenamingMeterFilter() {\n String prefix = "spring.batch.step";\n return MeterFilter.renameTag(prefix, prefix + ".job.name", "job.name");\n}\n\n\n\/**\n* @see org.springframework.batch.core.observability.BatchStepObservation.StepLowCardinalityTags#STEP_NAME\n*\/\n@Bean\nMeterFilter stepStepNameTagRenamingMeterFilter() {\n String prefix = "spring.batch.step";\n boolean batchV5 = ClassUtils.isPresent("org.springframework.batch.core.observability.BatchStepObservation", null);\n String from = batchV5 ? prefix + ".name" : "name";\n return MeterFilter.renameTag(prefix, from, "step.name");\n}\n<\/pre><\/div>\n\n\nCorrelating Metrics and Logging<\/h1>\n\n\n\n
Include the job name in log message attributes<\/h2>\n\n\n\n
\n\/**\n * Ensures that logging performed in the context of a batch job includes a {@code job.name} MDC entry.\n *\/\npublic class SubscriptionJobLauncher extends SimpleJobLauncher {\n\n private static final String MDC_KEY = "job.name";\n\n @Override\n public JobExecution run(Job job, JobParameters jobParameters) throws JobExecutionAlreadyRunningException, JobRestartException, JobInstanceAlreadyCompleteException, JobParametersInvalidException {\n try (var c = MDC.putCloseable(MDC_KEY, job.getName())) {\n return super.run(job, jobParameters);\n }\n }\n\n @Override\n public void setTaskExecutor(TaskExecutor taskExecutor) {\n super.setTaskExecutor(new MDCPopulatingTaskExecutor(taskExecutor));\n }\n\n private static class MDCPopulatingTaskExecutor implements TaskExecutor {\n private final TaskExecutor targetExecutor;\n\n MDCPopulatingTaskExecutor(TaskExecutor targetExecutor) {\n this.targetExecutor = targetExecutor;\n }\n\n @Override\n public void execute(Runnable task) {\n String mdcValue = MDC.get(MDC_KEY);\n if (mdcValue == null || targetExecutor instanceof SyncTaskExecutor) {\n targetExecutor.execute(task);\n } else {\n targetExecutor.execute(() -> {\n try (var c = MDC.putCloseable(MDC_KEY, mdcValue)) {\n task.run();\n }\n });\n }\n }\n }\n}\n<\/pre><\/div>\n\n\nEnsure Lightmin uses our own JobLauncher<\/h3>\n\n\n\n
\n@Component \npublic class SubscriptionSchedulerService extends DefaultSchedulerService {\n public SubscriptionSchedulerService(BeanRegistrar beanRegistrar, JobRepository jobRepository, JobRegistry jobRegistry) {\n super(beanRegistrar, jobRepository, jobRegistry);\n }\n\n @Override\n public JobLauncher createLobLauncher(TaskExecutorType taskExecutorType, JobRepository jobRepository) {\n return SubscriptionJobLauncher.forLightmin(taskExecutorType, jobRepository);\n }\n}\n<\/pre><\/div>\n\n\n\n\/**\n * @see org.tuxdevelop.spring.batch.lightmin.service.ServiceUtil#createJobLauncher(TaskExecutorType, JobRepository)\n*\/\nstatic SubscriptionJobLauncher forLightmin(TaskExecutorType taskExecutorType, JobRepository jobRepository) {\n var jobLauncher = new SubscriptionJobLauncher();\n jobLauncher.setJobRepository(jobRepository);\n if (taskExecutorType == TaskExecutorType.ASYNCHRONOUS) {\n jobLauncher.setTaskExecutor(new SimpleAsyncTaskExecutor());\n } else if (taskExecutorType == TaskExecutorType.SYNCHRONOUS) {\n jobLauncher.setTaskExecutor(new SyncTaskExecutor());\n }\n return jobLauncher;\n}\n<\/pre><\/div>\n\n\nEnsuring consistent tag name values: are we there yet?<\/h2>\n\n\n\n
We just covered the first: job names will now end up in our MDC using a \u201cjob.name\u201d key. We use structured JSON logging<\/a> that adds all MDC entries to our log message JSON document, and the Datadog agent will forward that to the server where these entries will show up as attributes.<\/p>\n\n\n\n![](\"https:\/\/lh7-us.googleusercontent.com\/J0dyAegRAFMkroAoqVmNN5FVQeaksxGmtUoBOpDWMiSPLzs0NAF1iLLnXdhN8LpEqZHfnKOjSoQT5TOQDCOcqwZIe6_aDCIMdb15J36N4LhqhYIy61dDhymKQdAg57R9I19S9fqAVkcS2bcVBYT8SFo\")
![](\"https:\/\/lh7-us.googleusercontent.com\/wSuwiqoOBkHU56eaZJzq0vDa8_LIYBlR9OWBFPOvIL_0kH5cb0bnRwINu9UifRhip5FDsl_UbYeYLw76mOFDYZeTvg4i4vOt670FlY8d5oe5iWjknOiirCM8SomvWOPWT4d8_2CleiF0VyzLbKsIo3A\")
Since we want consistency, I wrote a function that will rewrite the job names we put in the MDC to match Datadog\u2019s behavior:<\/p>\n\n\n\nstatic final Pattern ILLEGAL_CHARS = Pattern.compile("[^A-Za-z0-9_:.\/-]");\n\n\/**\n* Rewrites the given value in the same way that the value would end up as a Datadog metric tag value,\n* meaning it's lower-cased and non-allowed characters are converted to underscores.\n*\n* @param value to convert, may be {@code null}\n* @return converted value\n* @see <a href="https:\/\/docs.datadoghq.com\/getting_started\/tagging\/#define-tags">Datadog tag docs<\/a>\n*\/\npublic static String asDatadogTag(String value) {\n if (value == null) return null;\n return ILLEGAL_CHARS.matcher(value.toLowerCase()).replaceAll("_");\n}\n<\/pre><\/div>\n\n\nBuilding the Datadog dashboard<\/h1>\n\n\n\n
Right now we show what jobs failed and some info about their execution times. We also do that for steps and then include some info on chunks, although I\u2019m not sure yet how useful the latter will turn out to be.<\/p>\n\n\n\n