From bfd9ca6576da493d0d256bf8c7bba4eabe5a5d99 Mon Sep 17 00:00:00 2001 From: Francois Staudt Date: Mon, 14 Oct 2024 12:32:34 +0200 Subject: [PATCH] Log delta count in addition to throughput in LoggingMeterRegistry Closes #5548 --- .../logging/LoggingMeterRegistry.java | 26 ++-- .../logging/LoggingMeterRegistryTest.java | 129 +++++++++++++++++- 2 files changed, 139 insertions(+), 16 deletions(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java index 6cbea5b75b..bc4b499b0a 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java @@ -49,6 +49,7 @@ * * @author Jon Schneider * @author Matthieu Borgraeve + * @author Francois Staudt * @since 1.1.0 */ @Incubating(since = "1.1.0") @@ -114,6 +115,7 @@ private Function defaultMeterIdPrinter() { @Override protected void publish() { if (config.enabled()) { + loggingSink.accept("Step: " + config.step().getSeconds() + "s"); getMeters().stream().sorted((m1, m2) -> { int typeComp = m1.getId().getType().compareTo(m2.getId().getType()); if (typeComp == 0) { @@ -126,22 +128,24 @@ protected void publish() { double count = counter.count(); if (!config.logInactive() && count == 0) return; - loggingSink.accept(print.id() + " throughput=" + print.rate(count)); + loggingSink + .accept(print.id() + " delta_count=" + ((int) count) + " throughput=" + print.rate(count)); }, timer -> { HistogramSnapshot snapshot = timer.takeSnapshot(); long count = snapshot.count(); if (!config.logInactive() && count == 0) return; - loggingSink.accept(print.id() + " throughput=" + print.unitlessRate(count) + " mean=" - + print.time(snapshot.mean(getBaseTimeUnit())) + " max=" - + print.time(snapshot.max(getBaseTimeUnit()))); + loggingSink.accept(print.id() + " delta_count=" + ((int) count) + " throughput=" + + print.unitlessRate(count) + " mean=" + print.time(snapshot.mean(getBaseTimeUnit())) + + " max=" + print.time(snapshot.max(getBaseTimeUnit()))); }, summary -> { HistogramSnapshot snapshot = summary.takeSnapshot(); long count = snapshot.count(); if (!config.logInactive() && count == 0) return; - loggingSink.accept(print.id() + " throughput=" + print.unitlessRate(count) + " mean=" - + print.value(snapshot.mean()) + " max=" + print.value(snapshot.max())); + loggingSink.accept( + print.id() + " delta_count=" + ((int) count) + " throughput=" + print.unitlessRate(count) + + " mean=" + print.value(snapshot.mean()) + " max=" + print.value(snapshot.max())); }, longTaskTimer -> { int activeTasks = longTaskTimer.activeTasks(); if (!config.logInactive() && activeTasks == 0) @@ -157,13 +161,14 @@ protected void publish() { double count = counter.count(); if (!config.logInactive() && count == 0) return; - loggingSink.accept(print.id() + " throughput=" + print.rate(count)); + loggingSink + .accept(print.id() + " delta_count=" + ((int) count) + " throughput=" + print.rate(count)); }, timer -> { double count = timer.count(); if (!config.logInactive() && count == 0) return; - loggingSink.accept(print.id() + " throughput=" + print.rate(count) + " mean=" - + print.time(timer.mean(getBaseTimeUnit()))); + loggingSink.accept(print.id() + " delta_count=" + ((int) count) + " throughput=" + + print.unitlessRate(count) + " mean=" + print.time(timer.mean(getBaseTimeUnit()))); }, meter -> loggingSink.accept(writeMeter(meter, print))); }); } @@ -181,7 +186,8 @@ String writeMeter(Meter meter, Printer print) { case DURATION: return msLine + print.time(ms.getValue()); case COUNT: - return "throughput=" + print.rate(ms.getValue()); + return "delta_count=" + print.humanReadableBaseUnit(ms.getValue()) + ", throughput=" + + print.rate(ms.getValue()); default: return msLine + decimalOrNan(ms.getValue()); } diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java index 72fb2d42f2..087d56e61c 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java +++ b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java @@ -15,15 +15,22 @@ */ package io.micrometer.core.instrument.logging; +import com.google.common.util.concurrent.AtomicDouble; import io.micrometer.core.instrument.*; import io.micrometer.core.instrument.binder.BaseUnits; import org.junit.jupiter.api.Test; +import java.util.ArrayList; import java.util.Arrays; -import java.util.Collections; +import java.util.HashMap; +import java.util.List; +import java.util.Map; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicReference; +import java.util.stream.IntStream; +import static java.util.Collections.emptyList; +import static java.util.concurrent.TimeUnit.SECONDS; import static org.assertj.core.api.Assertions.assertThat; /** @@ -32,11 +39,20 @@ * @author Jon Schneider * @author Johnny Lim * @author Matthieu Borgraeve + * @author Francois Staudt */ class LoggingMeterRegistryTest { private final LoggingMeterRegistry registry = new LoggingMeterRegistry(); + private final ConfigurableLoggingRegistryConfig config = new ConfigurableLoggingRegistryConfig(); + + private final MockClock clock = new MockClock(); + + private final List logs = new ArrayList<>(); + + private final LoggingMeterRegistry spyLogRegistry = new LoggingMeterRegistry(config, clock, logs::add); + @Test void defaultMeterIdPrinter() { LoggingMeterRegistry registry = LoggingMeterRegistry.builder(LoggingRegistryConfig.DEFAULT).build(); @@ -110,22 +126,24 @@ void time() { @Test void writeMeterUnitlessValue() { - final String expectedResult = "meter.1{} value=0"; + final String expectedResult = "meter.1{} value=0, delta_count=30, throughput=0.5/s"; Measurement m1 = new Measurement(() -> 0d, Statistic.VALUE); - Meter meter = Meter.builder("meter.1", Meter.Type.OTHER, Collections.singletonList(m1)).register(registry); + Measurement m2 = new Measurement(() -> 30d, Statistic.COUNT); + Meter meter = Meter.builder("meter.1", Meter.Type.OTHER, List.of(m1, m2)).register(registry); LoggingMeterRegistry.Printer printer = registry.new Printer(meter); assertThat(registry.writeMeter(meter, printer)).isEqualTo(expectedResult); } @Test void writeMeterMultipleValues() { - final String expectedResult = "sheepWatch{color=black} value=5 sheep, max=1023 sheep, total=1.1s"; + final String expectedResult = "sheepWatch{color=black} value=5 sheep, max=1023 sheep, total=1.1s, delta_count=30 sheep, throughput=0.5 sheep/s"; Measurement m1 = new Measurement(() -> 5d, Statistic.VALUE); Measurement m2 = new Measurement(() -> 1023d, Statistic.MAX); Measurement m3 = new Measurement(() -> 1100d, Statistic.TOTAL_TIME); - Meter meter = Meter.builder("sheepWatch", Meter.Type.OTHER, Arrays.asList(m1, m2, m3)) + Measurement m4 = new Measurement(() -> 30d, Statistic.COUNT); + Meter meter = Meter.builder("sheepWatch", Meter.Type.OTHER, List.of(m1, m2, m3, m4)) .tag("color", "black") .description("Meter for shepherds.") .baseUnit("sheep") @@ -136,7 +154,7 @@ void writeMeterMultipleValues() { @Test void writeMeterByteValues() { - final String expectedResult = "bus-throughput{} throughput=5 B/s, value=64 B, value=2.125 KiB, value=8 MiB, value=1 GiB"; + final String expectedResult = "bus-throughput{} delta_count=300 B, throughput=5 B/s, value=64 B, value=2.125 KiB, value=8 MiB, value=1 GiB"; Measurement m1 = new Measurement(() -> 300d, Statistic.COUNT); Measurement m2 = new Measurement(() -> (double) (1 << 6), Statistic.VALUE); @@ -166,4 +184,103 @@ void printerValueWhenGaugeIsInfinityShouldPrintInfinity() { assertThat(printer.value(Double.POSITIVE_INFINITY)).isEqualTo("∞"); } + @Test + void publish_ShouldPrintDeltaCountAndThroughput_WhenMeterIsCounter() { + var counter = spyLogRegistry.counter("my.counter"); + counter.increment(30); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(logs).containsExactly("Step: 60s", "my.counter{} delta_count=30 throughput=0.5/s"); + } + + @Test + void publish_ShouldPrintDeltaCountAndThroughput_WhenMeterIsTimer() { + var timer = spyLogRegistry.timer("my.timer"); + IntStream.rangeClosed(1, 30).forEach(t -> timer.record(1, SECONDS)); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(logs).containsExactly("Step: 60s", "my.timer{} delta_count=30 throughput=0.5/s mean=1s max=1s"); + } + + @Test + void publish_ShouldPrintDeltaCountAndThroughput_WhenMeterIsSummary() { + var summary = spyLogRegistry.summary("my.summary"); + IntStream.rangeClosed(1, 30).forEach(t -> summary.record(1)); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(logs).containsExactly("Step: 60s", "my.summary{} delta_count=30 throughput=0.5/s mean=1 max=1"); + } + + @Test + void publish_ShouldPrintDeltaCountAndThroughput_WhenMeterIsFunctionCounter() { + spyLogRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 30); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(logs).containsExactly("Step: 60s", "my.function-counter{} delta_count=30 throughput=0.5/s"); + } + + @Test + void publish_ShouldPrintDeltaCountAndThroughput_WhenMeterIsFunctionTimer() { + spyLogRegistry.more().timer("my.function-timer", emptyList(), new AtomicDouble(), d -> 30, d -> 30, SECONDS); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(logs).containsExactly("Step: 60s", "my.function-timer{} delta_count=30 throughput=0.5/s mean=1s"); + } + + @Test + void publish_ShouldNotPrintAnything_WhenRegistryIsDisabled() { + config.set("enabled", "false"); + spyLogRegistry.counter("my.counter").increment(); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(spyLogRegistry.getMeters()).hasSize(1); + assertThat(logs).isEmpty(); + } + + @Test + void publish_ShouldOnlyPrintStepDuration_WhenStepCountIsZeroAndLogsInactiveIsDisabled() { + spyLogRegistry.counter("my.counter"); + spyLogRegistry.timer("my.timer"); + spyLogRegistry.summary("my.summary"); + spyLogRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 0); + spyLogRegistry.more().timer("my.function-timer", emptyList(), new AtomicDouble(), d -> 0, d -> 0, SECONDS); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(spyLogRegistry.getMeters()).hasSize(5); + assertThat(logs).containsExactly("Step: 60s"); + } + + @Test + void publish_ShouldPrintMetersWithZeroStepCount_WhenLogsInactiveIsEnabled() { + config.set("logInactive", "true"); + spyLogRegistry.counter("my.counter"); + spyLogRegistry.timer("my.timer"); + spyLogRegistry.summary("my.summary"); + spyLogRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 0); + spyLogRegistry.more().timer("my.function-timer", emptyList(), new AtomicDouble(), d -> 0, d -> 0, SECONDS); + clock.add(config.step()); + spyLogRegistry.publish(); + assertThat(spyLogRegistry.getMeters()).hasSize(5); + assertThat(logs).containsExactlyInAnyOrder("Step: 60s", "my.counter{} delta_count=0 throughput=0/s", + "my.timer{} delta_count=0 throughput=0/s mean= max=", + "my.summary{} delta_count=0 throughput=0/s mean=0 max=0", + "my.function-counter{} delta_count=0 throughput=0/s", + "my.function-timer{} delta_count=0 throughput=0/s mean="); + } + + private static class ConfigurableLoggingRegistryConfig implements LoggingRegistryConfig { + + private final Map keys = new HashMap<>(); + + @Override + public String get(String key) { + return keys.get(key); + } + + public void set(String key, String value) { + keys.put(prefix() + "." + key, value); + } + + } + }