Merge pull request #19192 from mkouba/scheduler-metrics

Scheduler - make it possible to record metrics automatically

docs/src/main/asciidoc/scheduler-reference.adoc

@@ -320,6 +320,14 @@ The scheduler can be disabled through the runtime config property `quarkus.sched
 If set to `false` the scheduler is not started even though the application contains scheduled methods.
 You can even disable the scheduler for particular <<getting-started-testing#testing_different_profiles,Test Profiles>>.
 
+== Metrics
+
+Some basic metrics are published out of the box if `quarkus.scheduler.metrics.enabled` is set to `true` and a metrics extension is present. 
+
+If the link:micrometer[Micrometer extension] is present, then a `@io.micrometer.core.annotation.Timed` interceptor binding is added to all `@Scheduled` methods automatically (unless it's already present) and a `io.micrometer.core.instrument.Timer` with name `scheduled.methods` and a `io.micrometer.core.instrument.LongTaskTimer` with name `scheduled.methods.running` are registered. The fully qualified name of the declaring class and the name of a `@Scheduled` method are used as tags.
+
+If the link:smallrye-metrics[SmallRye Metrics extension] is present, then a `@org.eclipse.microprofile.metrics.annotation.Timed`  interceptor binding is added to all `@Scheduled` methods automatically (unless it's already present) and a `org.eclipse.microprofile.metrics.Timer` is created for each `@Scheduled` method. The name consists of the fully qualified name of the declaring class and the name of a `@Scheduled` method. The timer has a tag `scheduled=true`.
+
 == Configuration Reference
 
 include::{generated-dir}/config/quarkus-scheduler.adoc[leveloffset=+1, opts=optional]

extensions/quartz/deployment/pom.xml

@@ -35,6 +35,11 @@
             <artifactId>quarkus-quartz</artifactId>
         </dependency>
 
+        <dependency>
+            <groupId>io.quarkus</groupId>
+            <artifactId>quarkus-smallrye-metrics-deployment</artifactId>
+            <scope>test</scope>
+        </dependency>
         <dependency>
             <groupId>io.quarkus</groupId>
             <artifactId>quarkus-junit5-internal</artifactId>

extensions/quartz/deployment/src/test/java/io/quarkus/quartz/test/metrics/Jobs.java

@@ -0,0 +1,25 @@
+package io.quarkus.quartz.test.metrics;
+
+import java.util.concurrent.CountDownLatch;
+
+import org.eclipse.microprofile.metrics.annotation.Timed;
+
+import io.quarkus.scheduler.Scheduled;
+
+public class Jobs {
+
+    static final CountDownLatch latch01 = new CountDownLatch(1);
+    static final CountDownLatch latch02 = new CountDownLatch(1);
+
+    @Scheduled(every = "1s")
+    void everySecond() {
+        latch01.countDown();
+    }
+
+    @Timed(name = "foo") // Extension should not override this annotation 
+    @Scheduled(every = "1s")
+    void anotherEverySecond() {
+        latch02.countDown();
+    }
+
+}

extensions/quartz/deployment/src/test/java/io/quarkus/quartz/test/metrics/MpTimedTest.java

@@ -0,0 +1,47 @@
+package io.quarkus.quartz.test.metrics;
+
+import static org.junit.jupiter.api.Assertions.assertNotNull;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import java.util.concurrent.TimeUnit;
+
+import javax.inject.Inject;
+
+import org.eclipse.microprofile.metrics.MetricID;
+import org.eclipse.microprofile.metrics.MetricRegistry;
+import org.eclipse.microprofile.metrics.Tag;
+import org.eclipse.microprofile.metrics.Timer;
+import org.jboss.shrinkwrap.api.ShrinkWrap;
+import org.jboss.shrinkwrap.api.asset.StringAsset;
+import org.jboss.shrinkwrap.api.spec.JavaArchive;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
+
+import io.quarkus.test.QuarkusUnitTest;
+
+public class MpTimedTest {
+
+    @RegisterExtension
+    static final QuarkusUnitTest test = new QuarkusUnitTest()
+            .setArchiveProducer(() -> ShrinkWrap.create(JavaArchive.class)
+                    .addClasses(Jobs.class)
+                    .addAsResource(new StringAsset("quarkus.scheduler.metrics.enabled=true"),
+                            "application.properties"));
+
+    @Inject
+    MetricRegistry metricRegistry;
+
+    @Test
+    void testTimedMethod() throws InterruptedException {
+        assertTrue(Jobs.latch01.await(5, TimeUnit.SECONDS));
+        assertTrue(Jobs.latch02.await(5, TimeUnit.SECONDS));
+        Timer timer1 = metricRegistry
+                .getTimer(new MetricID(Jobs.class.getName() + ".everySecond", new Tag("scheduled", "true")));
+        assertNotNull(timer1);
+        assertTrue(timer1.getCount() > 0);
+        Timer timer2 = metricRegistry.getTimer(new MetricID(Jobs.class.getName() + ".foo"));
+        assertNotNull(timer2);
+        assertTrue(timer2.getCount() > 0);
+    }
+
+}

extensions/scheduler/deployment/pom.xml

@@ -31,6 +31,11 @@
           <artifactId>quarkus-vertx-http-deployment</artifactId>
           <scope>test</scope>
       </dependency>
+      <dependency>
+          <groupId>io.quarkus</groupId>
+          <artifactId>quarkus-micrometer-registry-prometheus-deployment</artifactId>
+          <scope>test</scope>
+      </dependency>
       <dependency>
           <groupId>io.quarkus</groupId>
           <artifactId>quarkus-junit5-internal</artifactId>

extensions/scheduler/deployment/src/main/java/io/quarkus/scheduler/deployment/SchedulerProcessor.java

@@ -2,6 +2,10 @@
 
 import static io.quarkus.deployment.annotations.ExecutionTime.RUNTIME_INIT;
 import static io.quarkus.deployment.annotations.ExecutionTime.STATIC_INIT;
+import static org.jboss.jandex.AnnotationTarget.Kind.METHOD;
+import static org.jboss.jandex.AnnotationValue.createArrayValue;
+import static org.jboss.jandex.AnnotationValue.createBooleanValue;
+import static org.jboss.jandex.AnnotationValue.createStringValue;
 
 import java.lang.reflect.Modifier;
 import java.time.Duration;
@@ -11,6 +15,7 @@
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Optional;
 import java.util.function.Function;
 
 import org.jboss.jandex.AnnotationInstance;
@@ -31,6 +36,7 @@
 import io.quarkus.arc.InjectableBean;
 import io.quarkus.arc.InstanceHandle;
 import io.quarkus.arc.deployment.AdditionalBeanBuildItem;
+import io.quarkus.arc.deployment.AnnotationsTransformerBuildItem;
 import io.quarkus.arc.deployment.AutoAddScopeBuildItem;
 import io.quarkus.arc.deployment.BeanArchiveIndexBuildItem;
 import io.quarkus.arc.deployment.BeanDiscoveryFinishedBuildItem;
@@ -40,6 +46,7 @@
 import io.quarkus.arc.deployment.UnremovableBeanBuildItem.BeanClassAnnotationExclusion;
 import io.quarkus.arc.deployment.ValidationPhaseBuildItem;
 import io.quarkus.arc.deployment.ValidationPhaseBuildItem.ValidationErrorBuildItem;
+import io.quarkus.arc.processor.AnnotationsTransformer;
 import io.quarkus.arc.processor.BeanDeploymentValidator;
 import io.quarkus.arc.processor.BeanInfo;
 import io.quarkus.arc.processor.BuiltinScope;
@@ -57,13 +64,15 @@
 import io.quarkus.deployment.builditem.FeatureBuildItem;
 import io.quarkus.deployment.builditem.GeneratedClassBuildItem;
 import io.quarkus.deployment.builditem.nativeimage.ReflectiveClassBuildItem;
+import io.quarkus.deployment.metrics.MetricsCapabilityBuildItem;
 import io.quarkus.devconsole.spi.DevConsoleRouteBuildItem;
 import io.quarkus.devconsole.spi.DevConsoleRuntimeTemplateInfoBuildItem;
 import io.quarkus.gizmo.ClassCreator;
 import io.quarkus.gizmo.ClassOutput;
 import io.quarkus.gizmo.MethodCreator;
 import io.quarkus.gizmo.MethodDescriptor;
 import io.quarkus.gizmo.ResultHandle;
+import io.quarkus.runtime.metrics.MetricsFactory;
 import io.quarkus.runtime.util.HashUtil;
 import io.quarkus.scheduler.Scheduled;
 import io.quarkus.scheduler.ScheduledExecution;
@@ -263,6 +272,48 @@ public DevConsoleRouteBuildItem devConsole(BuildProducer<DevConsoleRuntimeTempla
         return new DevConsoleRouteBuildItem("schedules", "POST", recorder.invokeHandler());
     }
 
+    @BuildStep
+    public AnnotationsTransformerBuildItem metrics(SchedulerConfig config,
+            Optional<MetricsCapabilityBuildItem> metricsCapability) {
+
+        if (config.metricsEnabled && metricsCapability.isPresent()) {
+            DotName micrometerTimed = DotName.createSimple("io.micrometer.core.annotation.Timed");
+            DotName mpTimed = DotName.createSimple("org.eclipse.microprofile.metrics.annotation.Timed");
+
+            return new AnnotationsTransformerBuildItem(AnnotationsTransformer.builder()
+                    .appliesTo(METHOD)
+                    .whenContainsAny(List.of(SCHEDULED_NAME, SCHEDULES_NAME))
+                    .whenContainsNone(List.of(micrometerTimed,
+                            mpTimed, DotName.createSimple("org.eclipse.microprofile.metrics.annotation.SimplyTimed")))
+                    .transform(context -> {
+                        // Transform a @Scheduled method that has no metrics timed annotation
+                        MethodInfo scheduledMethod = context.getTarget().asMethod();
+                        if (metricsCapability.get().metricsSupported(MetricsFactory.MICROMETER)) {
+                            // Micrometer
+                            context.transform()
+                                    .add(micrometerTimed, createStringValue("value", "scheduled.methods"))
+                                    .add(micrometerTimed, createStringValue("value", "scheduled.methods.running"),
+                                            createBooleanValue("longTask", true))
+                                    .done();
+                            LOGGER.debugf("Added Micrometer @Timed to a @Scheduled method %s#%s()",
+                                    scheduledMethod.declaringClass().name(),
+                                    scheduledMethod.name());
+                        } else if (metricsCapability.get().metricsSupported(MetricsFactory.MP_METRICS)) {
+                            // MP metrics
+                            context.transform()
+                                    .add(mpTimed,
+                                            createArrayValue("tags",
+                                                    new AnnotationValue[] { createStringValue("scheduled", "scheduled=true") }))
+                                    .done();
+                            LOGGER.debugf("Added MP Metrics @Timed to a @Scheduled method %s#%s()",
+                                    scheduledMethod.declaringClass().name(),
+                                    scheduledMethod.name());
+                        }
+                    }));
+        }
+        return null;
+    }
+
     private String generateInvoker(ScheduledBusinessMethodItem scheduledMethod, ClassOutput classOutput) {
 
         BeanInfo bean = scheduledMethod.getBean();

extensions/scheduler/deployment/src/test/java/io/quarkus/scheduler/test/metrics/MicrometerTimedTest.java

@@ -0,0 +1,81 @@
+package io.quarkus.scheduler.test.metrics;
+
+import static org.junit.jupiter.api.Assertions.assertNotNull;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.TimeUnit;
+
+import javax.inject.Inject;
+
+import org.jboss.shrinkwrap.api.ShrinkWrap;
+import org.jboss.shrinkwrap.api.asset.StringAsset;
+import org.jboss.shrinkwrap.api.spec.JavaArchive;
+import org.junit.jupiter.api.BeforeAll;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
+
+import io.micrometer.core.annotation.Timed;
+import io.micrometer.core.instrument.MeterRegistry;
+import io.micrometer.core.instrument.Metrics;
+import io.micrometer.core.instrument.Timer;
+import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
+import io.quarkus.scheduler.Scheduled;
+import io.quarkus.test.QuarkusUnitTest;
+
+public class MicrometerTimedTest {
+
+    @RegisterExtension
+    static final QuarkusUnitTest test = new QuarkusUnitTest()
+            .setArchiveProducer(() -> ShrinkWrap.create(JavaArchive.class)
+                    .addClasses(Jobs.class)
+                    .addAsResource(new StringAsset("quarkus.scheduler.metrics.enabled=true"),
+                            "application.properties"));
+
+    @Inject
+    MeterRegistry registry;
+
+    @BeforeAll
+    static void addSimpleRegistry() {
+        Metrics.globalRegistry.add(new SimpleMeterRegistry());
+    }
+
+    @Test
+    void testTimedMethod() throws InterruptedException {
+        assertTrue(Jobs.latch01.await(5, TimeUnit.SECONDS));
+        assertTrue(Jobs.latch02.await(5, TimeUnit.SECONDS));
+        Timer timer1 = registry.get("scheduled.methods")
+                .tag("method", "everySecond")
+                .tag("class", "io.quarkus.scheduler.test.metrics.MicrometerTimedTest$Jobs")
+                .tag("exception", "none")
+                .timer();
+        assertNotNull(timer1);
+        assertTrue(timer1.count() > 0);
+        Timer timer2 = registry.get("foo")
+                .tag("method", "anotherEverySecond")
+                .tag("class", "io.quarkus.scheduler.test.metrics.MicrometerTimedTest$Jobs")
+                .tag("exception", "none")
+                .timer();
+        assertNotNull(timer2);
+        assertTrue(timer2.count() > 0);
+    }
+
+    static class Jobs {
+
+        static final CountDownLatch latch01 = new CountDownLatch(1);
+        static final CountDownLatch latch02 = new CountDownLatch(1);
+
+        @Scheduled(every = "1s")
+        void everySecond() {
+            latch01.countDown();
+        }
+
+        @Timed("foo") // Extension should not override this annotation 
+        @Scheduled(every = "1s")
+        void anotherEverySecond() {
+            latch02.countDown();
+        }
+
+    }
+
+}

extensions/scheduler/runtime/src/main/java/io/quarkus/scheduler/runtime/SchedulerConfig.java

@@ -18,4 +18,10 @@ public class SchedulerConfig {
     @ConfigItem(defaultValue = "quartz")
     public CronType cronType;
 
+    /**
+     * Scheduled task metrics will be enabled if a metrics extension is present and this value is true.
+     */
+    @ConfigItem(name = "metrics.enabled")
+    public boolean metricsEnabled;
+
 }