diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/report/ReporterConfiguration.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/report/ReporterConfiguration.java index b9425f8a26..5426354194 100644 --- a/apm-agent-core/src/main/java/co/elastic/apm/agent/report/ReporterConfiguration.java +++ b/apm-agent-core/src/main/java/co/elastic/apm/agent/report/ReporterConfiguration.java @@ -192,7 +192,8 @@ public class ReporterConfiguration extends ConfigurationOptionProvider { .key("metrics_interval") .tags("added[1.3.0]") .configurationCategory(REPORTER_CATEGORY) - .description("The interval at which the agent sends metrics to the APM Server.\n" + + .description("The interval at which the agent sends metrics to the APM Server, rounded down to the nearest second (ie 3783ms would be applied as 3000ms).\n" + + "If there is an interval (step) defined in the Meter, that interval (to the nearest second) will instead be used, for that Meter. If the Meter step interval is less than 1 second, the meter will not be reported.\n" + "Must be at least `1s`.\n" + "Set to `0s` to deactivate.") .addValidator(isNotInRange(TimeDuration.of("1ms"), TimeDuration.of("999ms"))) @@ -292,8 +293,9 @@ public long getApiRequestSize() { return apiRequestSize.get().getBytes(); } + //Only whole seconds are used, so drop the fractional part at 1 second resolution public long getMetricsIntervalMs() { - return metricsInterval.get().getMillis(); + return (metricsInterval.get().getMillis()/1000L)*1000L; } public List getDisableMetrics() { diff --git a/apm-agent-plugins/apm-micrometer-plugin/pom.xml b/apm-agent-plugins/apm-micrometer-plugin/pom.xml index 55dafd065e..d6511a9eeb 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/pom.xml +++ b/apm-agent-plugins/apm-micrometer-plugin/pom.xml @@ -16,6 +16,7 @@ 8 8 + true diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/AbstractMicrometerInstrumentation.java b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/AbstractMicrometerInstrumentation.java new file mode 100644 index 0000000000..80dbe0cac9 --- /dev/null +++ b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/AbstractMicrometerInstrumentation.java @@ -0,0 +1,40 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package co.elastic.apm.agent.micrometer; + +import co.elastic.apm.agent.bci.TracerAwareInstrumentation; +import co.elastic.apm.agent.impl.GlobalTracer; + +import java.util.Collection; +import java.util.Collections; + +public abstract class AbstractMicrometerInstrumentation extends TracerAwareInstrumentation { + + static final MicrometerMetricsReporter reporter = new MicrometerMetricsReporter(GlobalTracer.requireTracerImpl()); + + public Collection getInstrumentationGroupNames() { + return Collections.singletonList("micrometer"); + } + + @Override + public boolean includeWhenInstrumentationIsDisabled() { + return true; + } + +} diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerConfigInstrumentation.java b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerConfigInstrumentation.java new file mode 100644 index 0000000000..6409253df3 --- /dev/null +++ b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerConfigInstrumentation.java @@ -0,0 +1,59 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package co.elastic.apm.agent.micrometer; + +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.simple.SimpleConfig; +import net.bytebuddy.asm.Advice; +import net.bytebuddy.description.method.MethodDescription; +import net.bytebuddy.description.type.TypeDescription; +import net.bytebuddy.matcher.ElementMatcher; + +import static net.bytebuddy.matcher.ElementMatchers.isConstructor; +import static net.bytebuddy.matcher.ElementMatchers.named; +import static net.bytebuddy.matcher.ElementMatchers.takesArgument; +import static net.bytebuddy.matcher.ElementMatchers.takesNoArguments; + +/** + * SimpleMeterRegistry is constructed with a SimpleConfig, but the config is not accessible via + * a config() method because the superclass declares a config() which returns a different config + * private to the superclass, and the SimpleMeterRegistry doesn't override that nor provide a different + * method to access the SimpleConfig. So this instrumentation is just to access that config. + */ +public class MicrometerConfigInstrumentation extends AbstractMicrometerInstrumentation { + + @Override + public ElementMatcher getTypeMatcher() { + return named("io.micrometer.core.instrument.simple.SimpleMeterRegistry"); + } + + @Override + public ElementMatcher getMethodMatcher() { + return named("getMetersAsString").and(takesNoArguments()).or(isConstructor().and(takesArgument(0, named("io.micrometer.core.instrument.simple.SimpleConfig")))); + } + + public static class AdviceClass { + @Advice.OnMethodExit(suppress = Throwable.class, inline = false) + public static void onExit(@Advice.This MeterRegistry meterRegistry, @Advice.FieldValue("config") SimpleConfig config) { + reporter.addConfig(meterRegistry, config); + + } + } + +} diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentation.java b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentation.java index c758778ca8..a34b55a235 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentation.java +++ b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentation.java @@ -18,22 +18,15 @@ */ package co.elastic.apm.agent.micrometer; -import co.elastic.apm.agent.bci.TracerAwareInstrumentation; -import co.elastic.apm.agent.impl.GlobalTracer; import io.micrometer.core.instrument.MeterRegistry; import net.bytebuddy.asm.Advice; import net.bytebuddy.description.method.MethodDescription; import net.bytebuddy.description.type.TypeDescription; import net.bytebuddy.matcher.ElementMatcher; -import java.util.Collection; -import java.util.Collections; - import static net.bytebuddy.matcher.ElementMatchers.named; -public class MicrometerInstrumentation extends TracerAwareInstrumentation { - - private static final MicrometerMetricsReporter reporter = new MicrometerMetricsReporter(GlobalTracer.requireTracerImpl()); +public class MicrometerInstrumentation extends AbstractMicrometerInstrumentation { @Override public ElementMatcher getTypeMatcher() { @@ -45,16 +38,6 @@ public ElementMatcher getMethodMatcher() { return named("registerMeterIfNecessary"); } - @Override - public Collection getInstrumentationGroupNames() { - return Collections.singletonList("micrometer"); - } - - @Override - public boolean includeWhenInstrumentationIsDisabled() { - return true; - } - public static class AdviceClass { @Advice.OnMethodExit(suppress = Throwable.class, inline = false) public static void onExit(@Advice.This MeterRegistry meterRegistry) { diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporter.java b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporter.java index 2bdb061597..c0c6b0f443 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporter.java +++ b/apm-agent-plugins/apm-micrometer-plugin/src/main/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporter.java @@ -24,81 +24,198 @@ import co.elastic.apm.agent.matcher.WildcardMatcher; import co.elastic.apm.agent.report.Reporter; import co.elastic.apm.agent.report.ReporterConfiguration; +import co.elastic.apm.agent.sdk.logging.Logger; +import co.elastic.apm.agent.sdk.logging.LoggerFactory; import co.elastic.apm.agent.sdk.weakconcurrent.WeakConcurrent; -import co.elastic.apm.agent.sdk.weakconcurrent.WeakSet; +import co.elastic.apm.agent.sdk.weakconcurrent.WeakMap; import com.dslplatform.json.JsonWriter; import io.micrometer.core.instrument.Meter; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.composite.CompositeMeterRegistry; -import co.elastic.apm.agent.sdk.logging.Logger; -import co.elastic.apm.agent.sdk.logging.LoggerFactory; +import io.micrometer.core.instrument.simple.CountingMode; +import io.micrometer.core.instrument.simple.SimpleConfig; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import io.micrometer.core.instrument.step.StepRegistryConfig; import java.io.Closeable; +import java.time.Duration; import java.util.HashMap; +import java.util.HashSet; +import java.util.Iterator; import java.util.List; import java.util.Map; +import java.util.Set; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.Consumer; +/* +MeterRegistrys with CountingMode CUMULATIVE are eventually accurate, and rarely misleading +- typically the metric values are immediately correct, but in the worst case are eventually +correct (ie the metric being written may be a bit behind the last update, but will good enough) + +MeterRegistrys with CountingMode STEP update the accessible metric value each "step interval", +and in between they hold a cache of the last value, and that value is what is provided when +sampled. So if the agent metric interval is shorter, the agent will publish the cached +value at least once when it should be producing 0. + +Here, the agent takes the step interval as primary if that is being used, otherwise the +agent interval is used. But note that because we don't know exactly when the meter is +updated, and the scheduler here can drift long (take more than 1 second between checks), +it's possible that the agent drops the occasional sample + */ public class MicrometerMetricsReporter implements Runnable, Closeable { + //interval is actually this plus a random amount of ms more due to processing delays + //this means that an occasional step metric will be skipped. This is deemed acceptable + private static final long INTERVAL_BETWEEN_CHECKS_IN_MILLISECONDS = 1000L; private static final Logger logger = LoggerFactory.getLogger(MicrometerMetricsReporter.class); + private static final boolean HAS_SimpleMeterRegistry_METHOD; + static { + boolean hasSimpleMeterRegistryMethod1; + try { + Class simpleMeterRegistryClass = Class.forName("io.micrometer.core.instrument.simple.SimpleMeterRegistry"); + simpleMeterRegistryClass.getDeclaredMethod("getMetersAsString", new Class[0]); + hasSimpleMeterRegistryMethod1 = true; + } catch (NoSuchMethodException | ClassNotFoundException e) { + hasSimpleMeterRegistryMethod1 = false; + } + HAS_SimpleMeterRegistry_METHOD = hasSimpleMeterRegistryMethod1; + } - private final WeakSet meterRegistries = WeakConcurrent.buildSet(); + private volatile long lastMetricIntervalTimestamp = System.currentTimeMillis(); + + //Would have been cleaner to use MeterRegistryWrapper class, but they would get removed + //immediately from the weak set because nothing else points at them + private final WeakMap meterRegistries = WeakConcurrent.buildMap(); + private final WeakMap configMap = WeakConcurrent.buildMap(); private final MicrometerMeterRegistrySerializer serializer; private final Reporter reporter; private final ElasticApmTracer tracer; - private boolean scheduledReporting = false; + private final AtomicBoolean scheduledReporting = new AtomicBoolean(); + private final boolean disableScheduler; public MicrometerMetricsReporter(ElasticApmTracer tracer) { + this(tracer, false); + } + + //constructor split up to have this available for testing + MicrometerMetricsReporter(ElasticApmTracer tracer, boolean disableSchedulerThread) { this.tracer = tracer; this.reporter = tracer.getReporter(); tracer.addShutdownHook(this); serializer = new MicrometerMeterRegistrySerializer(tracer.getConfig(MetricsConfiguration.class)); + this.disableScheduler = disableSchedulerThread; } - public void registerMeterRegistry(MeterRegistry meterRegistry) { + void registerMeterRegistry(MeterRegistry meterRegistry) { if (meterRegistry instanceof CompositeMeterRegistry) { return; } - boolean added = meterRegistries.add(meterRegistry); - if (added) { + long step = getStep(meterRegistry); + if (step >= 0 && step < 1000) { + logger.warn("Not registering unsupported step interval of {} milliseconds (1 seconds is the minimum supported) for Micrometer MeterRegistry: {}", step, meterRegistry); + return; + } + Step newStep = new Step(step); + Step hopefullyNull = meterRegistries.putIfAbsent(meterRegistry, newStep); + if (hopefullyNull != null) { + logger.info("Not re-registering MeterRegistry as it is already registered from another compound meter registry: {}", meterRegistry); + } else { logger.info("Registering Micrometer MeterRegistry: {}", meterRegistry); - scheduleReporting(); } + scheduleReporting(); } private synchronized void scheduleReporting() { - if (scheduledReporting) { + if (disableScheduler) { return; } - scheduledReporting = true; - long metricsIntervalMs = tracer.getConfig(ReporterConfiguration.class).getMetricsIntervalMs(); - if (metricsIntervalMs > 0) { + if (scheduledReporting.compareAndSet(false, true)) { // called for every class loader that loaded micrometer // that's because a new MicrometerMetricsReporter instance is created in every IndyPluginClassLoader // for example if multiple webapps use potentially different versions of Micrometer - tracer.getSharedSingleThreadedPool().scheduleAtFixedRate(this, metricsIntervalMs, metricsIntervalMs, TimeUnit.MILLISECONDS); + tracer.getSharedSingleThreadedPool().scheduleAtFixedRate(this, 0, INTERVAL_BETWEEN_CHECKS_IN_MILLISECONDS, TimeUnit.MILLISECONDS); } } // guaranteed to be invoked by a single thread @Override public void run() { + run(System.currentTimeMillis()); + } + + //run split up to have this available for testing + void run(final long now) { if (tracer.getState() != Tracer.TracerState.RUNNING) { return; } - final long timestamp = System.currentTimeMillis() * 1000; - MeterMapConsumer meterConsumer = new MeterMapConsumer(tracer.getConfig(ReporterConfiguration.class).getDisableMetrics()); - for (MeterRegistry registry : meterRegistries) { + long metricsIntervalMs = tracer.getConfig(ReporterConfiguration.class).getMetricsIntervalMs(); + if (metricsIntervalMs == 0) { + //by checking here rather than at thread creation/non-creation, + //the interval can be dynamically updated and any new value will apply + return; + } + + //non-step metrics are reported every metricsInterval, + //step metrics are reported every step interval (step defined by the registry) + boolean reportNonStepMetrics = false; + if((now - lastMetricIntervalTimestamp) >= metricsIntervalMs) { + reportNonStepMetrics = true; + //non-atomic, but this is used single-threaded, it's only + //volatile for tests to be able to reset the value + lastMetricIntervalTimestamp += metricsIntervalMs; + } + + Iterator> registriesIterator = meterRegistries.iterator(); + final Set currentlyReportableRegistries = new HashSet<>(); + while(registriesIterator.hasNext()) { + Map.Entry meterRegistryStepEntry = registriesIterator.next(); + MeterRegistry meterRegistry = meterRegistryStepEntry.getKey(); + Step meterRegistryStep = meterRegistryStepEntry.getValue(); + if (meterRegistryStep.isStep()) { + logger.debug("Evaluating whether to report: step {}, interval(ms) {}, meterRegistry {}", meterRegistryStep.lastStepCount ,meterRegistryStep.stepInMs, meterRegistry); + if (meterRegistryStep.shouldReportNow(now)) { + currentlyReportableRegistries.add(meterRegistry); + meterRegistryStep.incrementToNextStep(now); + } + } else if (reportNonStepMetrics) { + currentlyReportableRegistries.add(meterRegistry); + } + } + + MeterMapConsumer meterConsumer = MeterMapConsumer.INSTANCE.reset(tracer.getConfig(ReporterConfiguration.class).getDisableMetrics()); + for (MeterRegistry registry : currentlyReportableRegistries) { registry.forEachMeter(meterConsumer); } logger.debug("Reporting {} meters", meterConsumer.meters.size()); - for (JsonWriter serializedMetricSet : serializer.serialize(meterConsumer.meters, timestamp)) { + for (JsonWriter serializedMetricSet : serializer.serialize(meterConsumer.meters, now * 1000)) { reporter.report(serializedMetricSet); } } + private long getStep(MeterRegistry meterRegistry) { + if (meterRegistry.config() instanceof StepRegistryConfig) { + return ((StepRegistryConfig) (meterRegistry.config())).step().toMillis(); + } + if (meterRegistry instanceof SimpleMeterRegistry) { + if (!configMap.containsKey(meterRegistry)) { + //Next is just used to trigger the side-effect of adding the config to the map + //But it's only available from micrometer 1.9.0 + if (HAS_SimpleMeterRegistry_METHOD) { + ((SimpleMeterRegistry) meterRegistry).getMetersAsString(); + } else { + return -1; + } + } + SimpleConfig config = configMap.get(meterRegistry); + return (config != null && CountingMode.STEP.equals(config.mode())) ? + config.step().toMillis() : -1; + } + //non-step registries + return -1; + } + @Override public void close() { // flushing out metrics before shutting down @@ -107,13 +224,21 @@ public void close() { } private static class MeterMapConsumer implements Consumer { + //Reuse an instance to reduce garbage churn + static final MeterMapConsumer INSTANCE = new MeterMapConsumer(null); - private final List disabledMetrics; + private List disabledMetrics; public MeterMapConsumer(List disabledMetrics) { this.disabledMetrics = disabledMetrics; } + public MeterMapConsumer reset(List disabledMetrics2){ + disabledMetrics = disabledMetrics2; + meters.clear(); + return this; + } + final Map meters = new HashMap<>(); @Override @@ -125,11 +250,76 @@ public void accept(Meter meter) { } } - WeakSet getMeterRegistries() { + public void addConfig(final MeterRegistry meterRegistry, final SimpleConfig config) { + if (configMap.putIfAbsent(meterRegistry, config) != null) { + return; + } + logger.warn("Identified Micrometer SimpleConfig: {}", config); + + //this next only happens during testing + //can't use instanceof or casts because of different classloaders + if (config.getClass().getName().equals("co.elastic.apm.agent.micrometer.MicrometerMetricsReporter$OneSecondStepSimpleConfig")) { + meterRegistry.counter("MicrometerMetricsReporter_OneSecondStepSimpleConfig").increment(config.hashCode()); + } + } + + static class Step { + long lastStepCount = 0; + long stepInMs; + + public Step(long step) { + stepInMs = step; + } + + public boolean isStep() { + return stepInMs > 0; + } + + public boolean shouldReportNow(long now) { + //I tried many implementations, relative time based and incremental time based + //this one aligned to the micrometer steps seems to work best + long newStepCount = now / stepInMs; + return newStepCount > lastStepCount; + } + + public void incrementToNextStep(long now) { + lastStepCount = now / stepInMs; + } + } + + //for testing only + WeakMap getMeterRegistries() { return meterRegistries; } + //for testing only Iterable getFailedMeters() { return serializer.getFailedMeters(); } + + //for testing only + void resetNow(long now) { + lastMetricIntervalTimestamp = now; + } + + //for testing only + //default SimpleMeterRegistry step is 1 minute (so would need to wait that long to see the metric!) + //This has a 1 second step and `meterRegistry` is set when config instrumentation matches + static class OneSecondStepSimpleConfig implements SimpleConfig{ + + @Override + public CountingMode mode() { + return CountingMode.STEP; + } + + @Override + public Duration step() { + return Duration.ofSeconds(1); + } + + @Override + public String get(String key) { + return null; + } + } } diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/main/resources/META-INF/services/co.elastic.apm.agent.sdk.ElasticApmInstrumentation b/apm-agent-plugins/apm-micrometer-plugin/src/main/resources/META-INF/services/co.elastic.apm.agent.sdk.ElasticApmInstrumentation index 0e5645a623..37dfe7fa1e 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/src/main/resources/META-INF/services/co.elastic.apm.agent.sdk.ElasticApmInstrumentation +++ b/apm-agent-plugins/apm-micrometer-plugin/src/main/resources/META-INF/services/co.elastic.apm.agent.sdk.ElasticApmInstrumentation @@ -1 +1,2 @@ co.elastic.apm.agent.micrometer.MicrometerInstrumentation +co.elastic.apm.agent.micrometer.MicrometerConfigInstrumentation diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerConfigInstrumentationTest.java b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerConfigInstrumentationTest.java new file mode 100644 index 0000000000..4ef15f8dd1 --- /dev/null +++ b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerConfigInstrumentationTest.java @@ -0,0 +1,125 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package co.elastic.apm.agent.micrometer; + +import co.elastic.apm.agent.MockReporter; +import co.elastic.apm.agent.MockTracer; +import co.elastic.apm.agent.bci.ElasticApmAgent; +import co.elastic.apm.agent.configuration.CoreConfiguration; +import co.elastic.apm.agent.configuration.SpyConfiguration; +import co.elastic.apm.agent.report.ReporterConfiguration; +import com.fasterxml.jackson.core.JsonProcessingException; +import com.fasterxml.jackson.databind.JsonNode; +import com.fasterxml.jackson.databind.ObjectMapper; +import io.micrometer.core.instrument.Clock; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import net.bytebuddy.agent.ByteBuddyAgent; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.stagemonitor.configuration.ConfigurationRegistry; + +import java.nio.charset.StandardCharsets; +import java.util.Arrays; +import java.util.List; +import java.util.stream.Collectors; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.doReturn; + +public class MicrometerConfigInstrumentationTest { + + private MockReporter reporter; + private ConfigurationRegistry config; + private final ObjectMapper objectMapper = new ObjectMapper(); + + @Before + public void setUp() { + config = SpyConfiguration.createSpyConfig(); + doReturn(50L).when(config.getConfig(ReporterConfiguration.class)).getMetricsIntervalMs(); + reporter = new MockReporter(); + } + + @After + public void tearDown() { + ElasticApmAgent.reset(); + } + + @Test + public void testConfigMapWasUpdated() { + ElasticApmAgent.initInstrumentation(MockTracer.createRealTracer(reporter, config), ByteBuddyAgent.install()); + MicrometerMetricsReporter.OneSecondStepSimpleConfig oneSecondStepSimpleConfig = new MicrometerMetricsReporter.OneSecondStepSimpleConfig(); + SimpleMeterRegistry registryOneSecondStep = new SimpleMeterRegistry(oneSecondStepSimpleConfig, Clock.SYSTEM); + registryOneSecondStep.counter("bar").increment(); + + reporter.awaitUntilAsserted(3000, () -> + assertThat(getSpecialCounterValue()).isEqualTo(oneSecondStepSimpleConfig.hashCode())); + } + + @Test + public void testConfigMapWasUpdatedWhenInstrumentConfigDisabled() { + doReturn(false).when(config.getConfig(CoreConfiguration.class)).isInstrument(); + ElasticApmAgent.initInstrumentation(MockTracer.createRealTracer(reporter, config), ByteBuddyAgent.install()); + MicrometerMetricsReporter.OneSecondStepSimpleConfig oneSecondStepSimpleConfig = new MicrometerMetricsReporter.OneSecondStepSimpleConfig(); + SimpleMeterRegistry registryOneSecondStep = new SimpleMeterRegistry(oneSecondStepSimpleConfig, Clock.SYSTEM); + registryOneSecondStep.counter("bar").increment(); + + reporter.awaitUntilAsserted(3000, () -> + assertThat(getSpecialCounterValue()).isEqualTo(oneSecondStepSimpleConfig.hashCode())); + } + + private Integer getSpecialCounterValue() { + int count = 0; + for (JsonNode metricSet : getMetricSets()) { + JsonNode metricsetNode = metricSet.get("metricset"); + if (metricsetNode != null) { + JsonNode samples = metricsetNode.get("samples"); + if (samples != null) { + //this is set by the instrumentation + JsonNode special = samples.get("MicrometerMetricsReporter_OneSecondStepSimpleConfig"); + if (special != null) { + return special.get("value").asInt(); + } + } + } + count++; + } + return null; + } + + private List getMetricSets() { + List metricSets = reporter.getBytes() + .stream() + .map(k -> new String(k, StandardCharsets.UTF_8)) + .flatMap(s -> Arrays.stream(s.split("\n"))) + .map(this::deserialize) + .collect(Collectors.toList()); + reporter.reset(); + return metricSets; + } + + private JsonNode deserialize(String json) { + System.out.println(json); + try { + return objectMapper.readTree(json); + } catch (JsonProcessingException e) { + throw new RuntimeException(e); + } + } +} diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationStepTest.java b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationStepTest.java new file mode 100644 index 0000000000..2a99fcacce --- /dev/null +++ b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationStepTest.java @@ -0,0 +1,217 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package co.elastic.apm.agent.micrometer; + +import co.elastic.apm.agent.MockReporter; +import co.elastic.apm.agent.MockTracer; +import co.elastic.apm.agent.bci.ElasticApmAgent; +import co.elastic.apm.agent.configuration.SpyConfiguration; +import co.elastic.apm.agent.report.ReporterConfiguration; +import com.fasterxml.jackson.core.JsonProcessingException; +import com.fasterxml.jackson.databind.JsonNode; +import com.fasterxml.jackson.databind.ObjectMapper; +import io.micrometer.core.instrument.Clock; +import io.micrometer.core.instrument.simple.CountingMode; +import io.micrometer.core.instrument.simple.SimpleConfig; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import net.bytebuddy.agent.ByteBuddyAgent; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.stagemonitor.configuration.ConfigurationRegistry; + +import java.nio.charset.StandardCharsets; +import java.time.Duration; +import java.util.Arrays; +import java.util.List; +import java.util.Objects; +import java.util.stream.Collectors; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.doReturn; + +// Tests will fail about 1% of the time because occasionally an interval metric +// is dropped (due to the timing of micrometer updates vs our sampling - +// we can't sample more often because micrometer transparently provides the +// previous value, so we'd be sending extra - erroneous - data if we did) +public class MicrometerInstrumentationStepTest { + + private MockReporter reporter; + private ConfigurationRegistry config; + private final ObjectMapper objectMapper = new ObjectMapper(); + private final FooBar foobar = new FooBar(0,0); + + @Before + public void setUp() { + config = SpyConfiguration.createSpyConfig(); + doReturn(30_000L).when(config.getConfig(ReporterConfiguration.class)).getMetricsIntervalMs(); + reporter = new MockReporter(); + } + + @After + public void tearDown() { + ElasticApmAgent.reset(); + } + + @Test + public void testStepVsCumulativeOnce() { + final FooBar result = new FooBar(0,1); + testStepVsCumulative(result, false); + } + + @Test + public void testStepVsCumulativeMultiple() { + final FooBar result = new FooBar(0,21); + testStepVsCumulative(result, true); + } + + @Test + public void testStepVsCumulativeMultipleSameInterval() { + doReturn(1_000L).when(config.getConfig(ReporterConfiguration.class)).getMetricsIntervalMs(); + final FooBar result = new FooBar(21,21); + testStepVsCumulative(result, true); + } + + public void testStepVsCumulative(final FooBar result, boolean startThread) { + ElasticApmAgent.initInstrumentation(MockTracer.createRealTracer(reporter, config), ByteBuddyAgent.install()); + final SimpleMeterRegistry registryOneSecondStep = new SimpleMeterRegistry(new SimpleConfig() { + @Override + public CountingMode mode() { + return CountingMode.STEP; + } + + @Override + public Duration step() { + return Duration.ofSeconds(1); + } + + @Override + public String get(String key) { + return null; + } + }, Clock.SYSTEM); + final SimpleMeterRegistry registryOneSecondCumulative = new SimpleMeterRegistry(new SimpleConfig() { + + @Override + public CountingMode mode() { + return CountingMode.CUMULATIVE; + } + + @Override + public Duration step() { + return Duration.ofSeconds(1); + } + + @Override + public String get(String key) { return null; } + }, Clock.SYSTEM); + registryOneSecondCumulative.counter("foo").increment(); + registryOneSecondStep.counter("bar").increment(); + + if (startThread) { + new Thread(new Runnable() { + @Override + public void run() { + for (int i = 0; i < 20; i++) { + registryOneSecondCumulative.counter("foo").increment(); + registryOneSecondStep.counter("bar").increment(); + try { + Thread.sleep(100); + } catch (InterruptedException e) { + } + } + } + }).start(); + } + reporter.awaitUntilAsserted(5000, () -> + assertThat(countFooBars()).isEqualTo(result)); + } + + + private FooBar countFooBars() { + for (JsonNode metricSet : getMetricSets()) { + JsonNode metricsetNode = metricSet.get("metricset"); + if (metricsetNode != null) { + JsonNode samples = metricsetNode.get("samples"); + if (samples != null) { + JsonNode bar = samples.get("bar"); + if (bar != null) { + foobar.barCount += bar.get("value").asInt(); + } + JsonNode foo = samples.get("foo"); + if (foo != null) { + foobar.fooCount = foo.get("value").asInt(); + } + } + } + } + return foobar; + } + + private List getMetricSets() { + List metricSets = reporter.getBytes() + .stream() + .map(k -> new String(k, StandardCharsets.UTF_8)) + .flatMap(s -> Arrays.stream(s.split("\n"))) + .map(this::deserialize) + .collect(Collectors.toList()); + reporter.reset(); + return metricSets; + } + + private JsonNode deserialize(String json) { + System.out.println(json); + try { + return objectMapper.readTree(json); + } catch (JsonProcessingException e) { + throw new RuntimeException(e); + } + } + + class FooBar { + private int fooCount = 0; + private int barCount = 0; + + public FooBar(int fooCount, int barCount) { + this.fooCount = fooCount; + this.barCount = barCount; + } + + @Override + public boolean equals(Object o) { + if (this == o) return true; + if (o == null || getClass() != o.getClass()) return false; + FooBar fooBar = (FooBar) o; + return fooCount == fooBar.fooCount && barCount == fooBar.barCount; + } + + @Override + public int hashCode() { + return Objects.hash(fooCount, barCount); + } + + @Override + public String toString() { + return "FooBar{" + + "fooCount=" + fooCount + + ", barCount=" + barCount + + '}'; + } + } +} diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationTest.java b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationTest.java index 3fb9b00dc5..279cbb1f4d 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationTest.java +++ b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationTest.java @@ -26,6 +26,9 @@ import co.elastic.apm.agent.report.ReporterConfiguration; import com.fasterxml.jackson.databind.JsonNode; import com.fasterxml.jackson.databind.ObjectMapper; +import io.micrometer.core.instrument.Clock; +import io.micrometer.core.instrument.simple.CountingMode; +import io.micrometer.core.instrument.simple.SimpleConfig; import io.micrometer.core.instrument.simple.SimpleMeterRegistry; import net.bytebuddy.agent.ByteBuddyAgent; import org.junit.After; @@ -33,6 +36,7 @@ import org.junit.Test; import org.stagemonitor.configuration.ConfigurationRegistry; +import java.time.Duration; import java.util.List; import static org.assertj.core.api.Assertions.assertThat; @@ -62,7 +66,7 @@ public void tearDown() { @Test public void testRegisterMeterRegistry() { ElasticApmAgent.initInstrumentation(MockTracer.createRealTracer(reporter, config), ByteBuddyAgent.install()); - SimpleMeterRegistry registry = new SimpleMeterRegistry(); + SimpleMeterRegistry registry = new SimpleMeterRegistry(new OneSecondStepSimpleConfig(), Clock.SYSTEM); registry.counter("foo").increment(); reporter.awaitUntilAsserted(() -> assertThat(countFooSamples()).isGreaterThanOrEqualTo(1)); } @@ -71,7 +75,7 @@ public void testRegisterMeterRegistry() { public void testReportedWhenInstrumentConfigDisabled() { doReturn(false).when(config.getConfig(CoreConfiguration.class)).isInstrument(); ElasticApmAgent.initInstrumentation(MockTracer.createRealTracer(reporter, config), ByteBuddyAgent.install()); - SimpleMeterRegistry registry = new SimpleMeterRegistry(); + SimpleMeterRegistry registry = new SimpleMeterRegistry(new OneSecondStepSimpleConfig(), Clock.SYSTEM); registry.counter("foo").increment(); reporter.awaitUntilAsserted(3000, () -> assertThat(countFooSamples()).isGreaterThanOrEqualTo(1)); } @@ -101,4 +105,25 @@ private int countFooSamples() { } return lastFooSamples; } + + //default SimpleMeterRegistry step is 1 minute (so would need to wait that long to see the metric!) + //This has a 1 second step and `meterRegistry` is set when config instrumentation matches + static class OneSecondStepSimpleConfig implements SimpleConfig { + + @Override + public CountingMode mode() { + return CountingMode.STEP; + } + + @Override + public Duration step() { + return Duration.ofSeconds(1); + } + + @Override + public String get(String key) { + return null; + } + } + } diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationVersionsIT.java b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationVersionsIT.java index 95d397b3e7..548779f2af 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationVersionsIT.java +++ b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerInstrumentationVersionsIT.java @@ -27,7 +27,7 @@ public class MicrometerInstrumentationVersionsIT { public MicrometerInstrumentationVersionsIT() throws Exception { this.runner = new TestClassWithDependencyRunner("io.micrometer", "micrometer-core", "1.0.1", - MicrometerInstrumentationTest.class + MicrometerInstrumentationTest.class, MicrometerInstrumentationTest.OneSecondStepSimpleConfig.class ); } diff --git a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporterTest.java b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporterTest.java index 608298fc01..55ffe92d0b 100644 --- a/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporterTest.java +++ b/apm-agent-plugins/apm-micrometer-plugin/src/test/java/co/elastic/apm/agent/micrometer/MicrometerMetricsReporterTest.java @@ -33,13 +33,13 @@ import io.micrometer.core.instrument.FunctionTimer; import io.micrometer.core.instrument.LongTaskTimer; import io.micrometer.core.instrument.MeterRegistry; -import io.micrometer.core.instrument.MockClock; import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Timer; import io.micrometer.core.instrument.composite.CompositeMeterRegistry; import io.micrometer.core.instrument.simple.CountingMode; import io.micrometer.core.instrument.simple.SimpleConfig; import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import io.micrometer.core.instrument.util.TimeUtils; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; @@ -52,6 +52,7 @@ import java.util.Optional; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicLong; import java.util.stream.Collectors; import static org.assertj.core.api.Assertions.assertThat; @@ -73,14 +74,15 @@ void setUp() { meterRegistry = new CompositeMeterRegistry(Clock.SYSTEM, List.of(nestedCompositeMeterRegistry)); reporter = new MockReporter(); tracer = MockTracer.createRealTracer(reporter); - doReturn(0L).when(tracer.getConfig(ReporterConfiguration.class)).getMetricsIntervalMs(); - metricsReporter = new MicrometerMetricsReporter(tracer); + doReturn(61_000L).when(tracer.getConfig(ReporterConfiguration.class)).getMetricsIntervalMs(); + metricsReporter = new MicrometerMetricsReporter(tracer, true); //all calls to run() are explicit from the tests + //note the default mode is CUMULATIVE, so no need to addConfig(meterRegistry, meterRegistryConfig); metricsReporter.registerMeterRegistry(meterRegistry); metricsReporter.registerMeterRegistry(nestedCompositeMeterRegistry); metricsReporter.registerMeterRegistry(simpleMeterRegistry); - assertThat(metricsReporter.getMeterRegistries()).doesNotContain(meterRegistry); - assertThat(metricsReporter.getMeterRegistries()).doesNotContain(nestedCompositeMeterRegistry); - assertThat(metricsReporter.getMeterRegistries()).contains(simpleMeterRegistry); + assertThat(metricsReporter.getMeterRegistries().containsKey(meterRegistry)).isFalse(); + assertThat(metricsReporter.getMeterRegistries().containsKey(nestedCompositeMeterRegistry)).isFalse(); + assertThat(metricsReporter.getMeterRegistries().containsKey(simpleMeterRegistry)).isTrue(); } @AfterEach @@ -198,6 +200,14 @@ void testCounter() { assertThat(metricSet.get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(42); } + @Test + void testCounterWithMetricsIntervalDisabled() { + doReturn(0L).when(tracer.getConfig(ReporterConfiguration.class)).getMetricsIntervalMs(); + meterRegistry.counter("counter", List.of(Tag.of("foo", "bar"), Tag.of("baz", "qux"))).increment(42); + List metricSets = getMetricSets(null); + assertThat(metricSets).isEmpty(); + } + @Test void testFunctionCounter() { FunctionCounter.builder("counter", 42, i -> i).tag("foo", "bar").register(meterRegistry); @@ -207,10 +217,51 @@ void testFunctionCounter() { assertThat(metricSet.get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(42); } + @Test + void testStepCounterIntervalTakesPrecedenceAndNoReportBeforeFirstStep() { + ThreadSafeMockClock clock = new ThreadSafeMockClock(); + metricsReporter.resetNow(clock.wallTime()); + SimpleConfig meterRegistryConfig = new SimpleConfig() { + + @Override + public CountingMode mode() { + return CountingMode.STEP; + } + + @Override + public Duration step() { + return Duration.ofSeconds(10); + } + + @Override + public String get(@Nonnull String key) { + return null; + } + }; + meterRegistry = new SimpleMeterRegistry(meterRegistryConfig, clock); + metricsReporter.addConfig(meterRegistry, meterRegistryConfig); + metricsReporter.registerMeterRegistry(meterRegistry); + meterRegistry.counter("counter").increment(); + clock.add(5, TimeUnit.SECONDS); + List metricSets = getMetricSets(clock); + //interval is 30s but step is 10s so that 10s should take precedence + //which means after 5 seconds there should be no value reported + assertThat(metricSets).isEmpty(); + + //but after 15 seconds there should be an entry + clock.add(10, TimeUnit.SECONDS); + metricSets = getMetricSets(clock); + assertThat(metricSets).hasSize(1); + assertThat(metricSets.get(0).get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(1); + System.out.println("E-- "+meterRegistry.counter("counter").count()); + } + @Test void testCounterReset() { - MockClock clock = new MockClock(); - meterRegistry = new SimpleMeterRegistry(new SimpleConfig() { + ThreadSafeMockClock clock = new ThreadSafeMockClock(); + metricsReporter.resetNow(clock.wallTime()); + SimpleConfig meterRegistryConfig; + meterRegistry = new SimpleMeterRegistry(meterRegistryConfig = new SimpleConfig() { @Override public CountingMode mode() { @@ -227,14 +278,15 @@ public String get(@Nonnull String key) { return null; } }, clock); + metricsReporter.addConfig(meterRegistry, meterRegistryConfig); metricsReporter.registerMeterRegistry(meterRegistry); meterRegistry.counter("counter").increment(); - clock.addSeconds(30); - assertThat(getSingleMetricSet().get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(1); + clock.addSeconds(31); + assertThat(getSingleMetricSet(clock).get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(1); clock.addSeconds(30); - assertThat(getSingleMetricSet().get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(0); + assertThat(getSingleMetricSet(clock).get("metricset").get("samples").get("counter").get("value").doubleValue()).isEqualTo(0); } @Test @@ -475,13 +527,28 @@ void tryToSerializeInvalidTimeGaugeValues() { } private JsonNode getSingleMetricSet() { - List metricSets = getMetricSets(); + return getSingleMetricSet(null); + } + private JsonNode getSingleMetricSet(Clock clock) { + List metricSets = getMetricSets(clock); assertThat(metricSets).hasSize(1); return metricSets.get(0); } private List getMetricSets() { - metricsReporter.run(); + return getMetricSets(null); + } + private List getMetricSets(Clock clock) { + if (clock == null) { + //default tests use a +61seconds invocation, as the default + //SimpleMeterRegistry interval is 60 seconds + long now = System.currentTimeMillis(); + metricsReporter.resetNow(now); + metricsReporter.run(now + 61*1000L); + } else { + //Assume the caller has reset to some appropriate time + metricsReporter.run(clock.wallTime()); + } List metricSets = reporter.getBytes() .stream() .map(k -> new String(k, StandardCharsets.UTF_8)) @@ -500,4 +567,34 @@ private JsonNode deserialize(String json) { throw new RuntimeException(e); } } + + public class ThreadSafeMockClock implements Clock { + + // has to be non-zero to prevent divide-by-zeroes and other weird math results based + // on the clock + private AtomicLong timeNanos = new AtomicLong((long) TimeUtils.millisToUnit(1, TimeUnit.NANOSECONDS)); + + @Override + public long monotonicTime() { + return timeNanos.get(); + } + + @Override + public long wallTime() { + return TimeUnit.MILLISECONDS.convert(timeNanos.get(), TimeUnit.NANOSECONDS); + } + + public long add(long amount, TimeUnit unit) { + return timeNanos.addAndGet(unit.toNanos(amount)); + } + + public long add(Duration duration) { + return add(duration.toNanos(), TimeUnit.NANOSECONDS); + } + + public long addSeconds(long amount) { + return add(amount, TimeUnit.SECONDS); + } + + } } diff --git a/docs/configuration.asciidoc b/docs/configuration.asciidoc index 7235373525..e459b8920c 100644 --- a/docs/configuration.asciidoc +++ b/docs/configuration.asciidoc @@ -2767,7 +2767,8 @@ Allowed byte units are `b`, `kb` and `mb`. `1kb` is equal to `1024b`. [[config-metrics-interval]] ==== `metrics_interval` (added[1.3.0]) -The interval at which the agent sends metrics to the APM Server. +The interval at which the agent sends metrics to the APM Server, rounded down to the nearest second (ie 3783ms would be applied as 3000ms). +If there is an interval (step) defined in the Meter, that interval (to the nearest second) will instead be used, for that Meter. If the Meter step interval is less than 1 second, the meter will not be reported. Must be at least `1s`. Set to `0s` to deactivate. @@ -4340,7 +4341,8 @@ Example: `5ms`. # # api_request_size=768kb -# The interval at which the agent sends metrics to the APM Server. +# The interval at which the agent sends metrics to the APM Server, rounded down to the nearest second (ie 3783ms would be applied as 3000ms). +# If there is an interval (step) defined in the Meter, that interval (to the nearest second) will instead be used, for that Meter. If the Meter step interval is less than 1 second, the meter will not be reported. # Must be at least `1s`. # Set to `0s` to deactivate. #