Skip to content

Commit

Permalink
Log delta count in addition to throughput in LoggingMeterRegistry (mi…
Browse files Browse the repository at this point in the history 
…crometer-metrics#5590)

* Log delta count in addition to throughput in LoggingMeterRegistry

Closes micrometer-metrics#5548

* Log delta count in addition to throughput in LoggingMeterRegistry

Closes micrometer-metrics#5548

* Log delta count in addition to throughput in LoggingMeterRegistry

Closes micrometer-metrics#5548

---------

Co-authored-by: Francois Staudt <francois.staudt@soprabanking.com>
  • Loading branch information
@fstaudt
fstaudt and Francois Staudt authored Jan 9, 2025
1 parent 7fd577c commit 7f3c478
Show file tree
Hide file tree
Showing 2 changed files with 158 additions and 16 deletions.
26 changes: 16 additions & 10 deletions ...ometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,13 +42,15 @@
import java.util.stream.StreamSupport;

import static io.micrometer.core.instrument.util.DoubleFormat.decimalOrNan;
import static io.micrometer.core.instrument.util.DoubleFormat.wholeOrDecimal;
import static java.util.stream.Collectors.joining;

/**
* Logging {@link io.micrometer.core.instrument.MeterRegistry}.
*
* @author Jon Schneider
* @author Matthieu Borgraeve
* @author Francois Staudt
* @since 1.1.0
*/
@Incubating(since = "1.1.0")
Expand Down Expand Up @@ -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=" + print.humanReadableBaseUnit(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=" + wholeOrDecimal(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=" + wholeOrDecimal(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)
Expand All @@ -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=" + print.humanReadableBaseUnit(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=" + wholeOrDecimal(count) + " throughput="
+ print.unitlessRate(count) + " mean=" + print.time(timer.mean(getBaseTimeUnit())));
}, meter -> loggingSink.accept(writeMeter(meter, print)));
});
}
Expand All @@ -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());
}
Expand Down
148 changes: 142 additions & 6 deletions ...er-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

/**
Expand All @@ -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<String> logs = new ArrayList<>();

private final LoggingMeterRegistry spyLogRegistry = new LoggingMeterRegistry(config, clock, logs::add);

@Test
void defaultMeterIdPrinter() {
LoggingMeterRegistry registry = LoggingMeterRegistry.builder(LoggingRegistryConfig.DEFAULT).build();
Expand Down Expand Up @@ -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")
Expand All @@ -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);
Expand Down Expand Up @@ -166,4 +184,122 @@ void printerValueWhenGaugeIsInfinityShouldPrintInfinity() {
assertThat(printer.value(Double.POSITIVE_INFINITY)).isEqualTo("∞");
}

@Test
void publish_ShouldPrintDeltaCountAndThroughputWithBaseUnit_WhenMeterIsCounter() {
var counter = Counter.builder("my.counter").baseUnit("sheep").register(spyLogRegistry);
counter.increment(30);
clock.add(config.step());
spyLogRegistry.publish();
assertThat(logs).containsExactly("my.counter{} delta_count=30 sheep throughput=0.5 sheep/s");
}

@Test
void publish_ShouldPrintDeltaCountAsDecimal_WhenMeterIsCounterAndCountIsDecimal() {
var counter = spyLogRegistry.counter("my.counter");
counter.increment(0.5);
clock.add(config.step());
spyLogRegistry.publish();
assertThat(logs).containsExactly("my.counter{} delta_count=0.5 throughput=0.008333/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("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("my.summary{} delta_count=30 throughput=0.5/s mean=1 max=1");
}

@Test
void publish_ShouldPrintDeltaCountAndThroughputWithBaseUnit_WhenMeterIsFunctionCounter() {
FunctionCounter.builder("my.function-counter", new AtomicDouble(), d -> 30)
.baseUnit("sheep")
.register(spyLogRegistry);
clock.add(config.step());
spyLogRegistry.publish();
assertThat(logs).containsExactly("my.function-counter{} delta_count=30 sheep throughput=0.5 sheep/s");
}

@Test
void publish_ShouldPrintDeltaCountAsDecimal_WhenMeterIsFunctionCounterAndCountIsDecimal() {
spyLogRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 0.5);
clock.add(config.step());
spyLogRegistry.publish();
assertThat(logs).containsExactly("my.function-counter{} delta_count=0.5 throughput=0.008333/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("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_ShouldNotPrintAnything_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).isEmpty();
}

@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("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<String, String> 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);
}

}

}

0 comments on commit 7f3c478

Please sign in to comment.