From 10f22819963145482deeed2ff13004b3a21ab5a9 Mon Sep 17 00:00:00 2001 From: Mahmoud Ben Hassine Date: Thu, 16 May 2019 14:52:21 +0200 Subject: [PATCH] Show job execution duration in the logs Resolves BATCH-2775 --- .../launch/support/SimpleJobLauncher.java | 9 +- .../batch/core/metrics/BatchMetrics.java | 63 ++++++++++++-- .../sample/metrics/BatchMetricsTests.java | 84 +++++++++++++++++++ 3 files changed, 147 insertions(+), 9 deletions(-) diff --git a/spring-batch-core/src/main/java/org/springframework/batch/core/launch/support/SimpleJobLauncher.java b/spring-batch-core/src/main/java/org/springframework/batch/core/launch/support/SimpleJobLauncher.java index 57a73d34a..fdd14fff8 100644 --- a/spring-batch-core/src/main/java/org/springframework/batch/core/launch/support/SimpleJobLauncher.java +++ b/spring-batch-core/src/main/java/org/springframework/batch/core/launch/support/SimpleJobLauncher.java @@ -1,5 +1,5 @@ /* - * Copyright 2006-2018 the original author or authors. + * Copyright 2006-2019 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -15,6 +15,8 @@ */ package org.springframework.batch.core.launch.support; +import java.time.Duration; + import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.springframework.batch.core.BatchStatus; @@ -26,6 +28,7 @@ import org.springframework.batch.core.JobParameters; import org.springframework.batch.core.JobParametersInvalidException; import org.springframework.batch.core.StepExecution; import org.springframework.batch.core.launch.JobLauncher; +import org.springframework.batch.core.metrics.BatchMetrics; import org.springframework.batch.core.repository.JobExecutionAlreadyRunningException; import org.springframework.batch.core.repository.JobInstanceAlreadyCompleteException; import org.springframework.batch.core.repository.JobRepository; @@ -142,8 +145,10 @@ public class SimpleJobLauncher implements JobLauncher, InitializingBean { logger.info("Job: [" + job + "] launched with the following parameters: [" + jobParameters + "]"); job.execute(jobExecution); + Duration jobExecutionDuration = BatchMetrics.calculateDuration(jobExecution.getStartTime(), jobExecution.getEndTime()); logger.info("Job: [" + job + "] completed with the following parameters: [" + jobParameters - + "] and the following status: [" + jobExecution.getStatus() + "]"); + + "] and the following status: [" + jobExecution.getStatus() + "]" + + (jobExecutionDuration == null ? "" : " in " + BatchMetrics.formatDuration(jobExecutionDuration))); } catch (Throwable t) { logger.info("Job: [" + job diff --git a/spring-batch-core/src/main/java/org/springframework/batch/core/metrics/BatchMetrics.java b/spring-batch-core/src/main/java/org/springframework/batch/core/metrics/BatchMetrics.java index 4528f0671..8384647da 100644 --- a/spring-batch-core/src/main/java/org/springframework/batch/core/metrics/BatchMetrics.java +++ b/spring-batch-core/src/main/java/org/springframework/batch/core/metrics/BatchMetrics.java @@ -15,7 +15,10 @@ */ package org.springframework.batch.core.metrics; +import java.time.Duration; import java.util.Arrays; +import java.util.Date; +import java.util.concurrent.TimeUnit; import java.util.function.Supplier; import io.micrometer.core.instrument.Counter; @@ -25,9 +28,17 @@ import io.micrometer.core.instrument.Metrics; import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Timer; +import org.springframework.lang.Nullable; + /** - * Main entry point to interact with Micrometer's {@link Metrics#globalRegistry}. - * Provides common metrics such as {@link Timer}, {@link Counter} and {@link Gauge}. + * Central class for batch metrics. It provides: + * + * * * Only intended for internal use. * @@ -46,7 +57,6 @@ public final class BatchMetrics { /** * Create a {@link Timer}. - * * @param name of the timer. Will be prefixed with {@link BatchMetrics#METRICS_PREFIX}. * @param description of the timer * @param tags of the timer @@ -61,7 +71,6 @@ public final class BatchMetrics { /** * Create a new {@link Timer.Sample}. - * * @return a new timer sample instance */ public static Timer.Sample createTimerSample() { @@ -70,7 +79,6 @@ public final class BatchMetrics { /** * Create a new {@link LongTaskTimer}. - * * @param name of the long task timer. Will be prefixed with {@link BatchMetrics#METRICS_PREFIX}. * @param description of the long task timer. * @param tags of the timer @@ -85,7 +93,6 @@ public final class BatchMetrics { /** * Create a new {@link Counter}. - * * @param name of the counter. Will be prefixed with {@link BatchMetrics#METRICS_PREFIX}. * @param description of the counter * @param tags of the counter @@ -100,7 +107,6 @@ public final class BatchMetrics { /** * Create a new {@link Gauge}. - * * @param name of the gauge. Will be prefixed with {@link BatchMetrics#METRICS_PREFIX}. * @param description of the gauge * @param supplier A supplier that yields a value for the gauge. @@ -114,4 +120,47 @@ public final class BatchMetrics { .register(Metrics.globalRegistry); } + /** + * Calculate the duration between two dates. + * @param startTime the start time + * @param endTime the end time + * @return the duration between start time and end time + */ + @Nullable + public static Duration calculateDuration(@Nullable Date startTime, @Nullable Date endTime) { + if (startTime == null || endTime == null) { + return null; + } + return Duration.between(startTime.toInstant(), endTime.toInstant()); + } + + /** + * Format a duration in a human readable format like: 2h32m15s10ms. + * @param duration to format + * @return A human readable duration + */ + public static String formatDuration(@Nullable Duration duration) { + if (duration == null || duration.isZero() || duration.isNegative()) { + return ""; + } + StringBuilder formattedDuration = new StringBuilder(); + long hours = duration.toHours(); + long minutes = duration.toMinutes(); + long seconds = duration.getSeconds(); + long millis = duration.toMillis(); + if (hours != 0) { + formattedDuration.append(hours).append("h"); + } + if (minutes != 0) { + formattedDuration.append(minutes - TimeUnit.HOURS.toMinutes(hours)).append("m"); + } + if (seconds != 0) { + formattedDuration.append(seconds - TimeUnit.MINUTES.toSeconds(minutes)).append("s"); + } + if (millis != 0) { + formattedDuration.append(millis - TimeUnit.SECONDS.toMillis(seconds)).append("ms"); + } + return formattedDuration.toString(); + } + } diff --git a/spring-batch-samples/src/test/java/org/springframework/batch/sample/metrics/BatchMetricsTests.java b/spring-batch-samples/src/test/java/org/springframework/batch/sample/metrics/BatchMetricsTests.java index a05163072..e9fea17f6 100644 --- a/spring-batch-samples/src/test/java/org/springframework/batch/sample/metrics/BatchMetricsTests.java +++ b/spring-batch-samples/src/test/java/org/springframework/batch/sample/metrics/BatchMetricsTests.java @@ -15,7 +15,12 @@ */ package org.springframework.batch.sample.metrics; +import java.time.Duration; +import java.time.LocalDateTime; +import java.time.ZoneOffset; +import java.time.temporal.ChronoUnit; import java.util.Arrays; +import java.util.Date; import java.util.List; import io.micrometer.core.instrument.Meter; @@ -31,6 +36,7 @@ import org.springframework.batch.core.configuration.annotation.EnableBatchProces import org.springframework.batch.core.configuration.annotation.JobBuilderFactory; import org.springframework.batch.core.configuration.annotation.StepBuilderFactory; import org.springframework.batch.core.launch.JobLauncher; +import org.springframework.batch.core.metrics.BatchMetrics; import org.springframework.batch.item.ItemReader; import org.springframework.batch.item.ItemWriter; import org.springframework.batch.item.support.ListItemReader; @@ -41,6 +47,7 @@ import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNull; import static org.junit.Assert.assertTrue; import static org.junit.Assert.fail; @@ -48,6 +55,83 @@ public class BatchMetricsTests { private static final int EXPECTED_SPRING_BATCH_METRICS = 6; + @Test + public void testCalculateDuration() { + LocalDateTime startTime = LocalDateTime.now(); + LocalDateTime endTime = startTime + .plus(2, ChronoUnit.HOURS) + .plus(31, ChronoUnit.MINUTES) + .plus(12, ChronoUnit.SECONDS) + .plus(42, ChronoUnit.MILLIS); + + Duration duration = BatchMetrics.calculateDuration(toDate(startTime), toDate(endTime)); + Duration expectedDuration = Duration.ofMillis(42).plusSeconds(12).plusMinutes(31).plusHours(2); + assertEquals(expectedDuration, duration); + } + + @Test + public void testCalculateDurationWhenNoStartTime() { + Duration duration = BatchMetrics.calculateDuration(null, toDate(LocalDateTime.now())); + assertNull(duration); + } + + @Test + public void testCalculateDurationWhenNoEndTime() { + Duration duration = BatchMetrics.calculateDuration(toDate(LocalDateTime.now()), null); + assertNull(duration); + } + + private Date toDate(LocalDateTime localDateTime) { + return Date.from(localDateTime.toInstant(ZoneOffset.UTC)); + } + + @Test + public void testFormatValidDuration() { + Duration duration = Duration.ofMillis(42).plusSeconds(12).plusMinutes(31).plusHours(2); + String formattedDuration = BatchMetrics.formatDuration(duration); + assertEquals("2h31m12s42ms", formattedDuration); + } + + @Test + public void testFormatValidDurationWithoutHours() { + Duration duration = Duration.ofMillis(42).plusSeconds(12).plusMinutes(31); + String formattedDuration = BatchMetrics.formatDuration(duration); + assertEquals("31m12s42ms", formattedDuration); + } + + @Test + public void testFormatValidDurationWithoutMinutes() { + Duration duration = Duration.ofMillis(42).plusSeconds(12); + String formattedDuration = BatchMetrics.formatDuration(duration); + assertEquals("12s42ms", formattedDuration); + } + + @Test + public void testFormatValidDurationWithoutSeconds() { + Duration duration = Duration.ofMillis(42); + String formattedDuration = BatchMetrics.formatDuration(duration); + assertEquals("42ms", formattedDuration); + } + + @Test + public void testFormatNegativeDuration() { + Duration duration = Duration.ofMillis(-1); + String formattedDuration = BatchMetrics.formatDuration(duration); + assertTrue(formattedDuration.isEmpty()); + } + + @Test + public void testFormatZeroDuration() { + String formattedDuration = BatchMetrics.formatDuration(Duration.ZERO); + assertTrue(formattedDuration.isEmpty()); + } + + @Test + public void testFormatNullDuration() { + String formattedDuration = BatchMetrics.formatDuration(null); + assertTrue(formattedDuration.isEmpty()); + } + @Test public void testBatchMetrics() throws Exception { // given