Skip to content

Commit

Permalink
Log delta count in addition to throughput in LoggingMeterRegistry
Browse files Browse the repository at this point in the history 
Closes #5548
  • Loading branch information
Francois Staudt committed Oct 14, 2024
1 parent eff8a61 commit bfd9ca6
Show file tree
Hide file tree
Showing 2 changed files with 139 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 @@ -49,6 +49,7 @@
*
* @author Jon Schneider
* @author Matthieu Borgraeve
* @author Francois Staudt
* @since 1.1.0
*/
@Incubating(since = "1.1.0")
Expand Down Expand Up @@ -114,6 +115,7 @@ private Function<Meter, String> 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) {
Expand All @@ -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)
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=" + ((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)));
});
}
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
129 changes: 123 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,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<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 bfd9ca6

Please sign in to comment.