Monitor rule execution duration

bundles/org.openhab.core.io.monitor/src/main/java/org/openhab/core/io/monitor/internal/metrics/EventCountMetric.java

@@ -40,7 +40,7 @@
 @NonNullByDefault
 public class EventCountMetric implements OpenhabCoreMeterBinder, EventSubscriber {
 
-    public static final String METRIC_NAME = "event_count";
+    public static final String METRIC_NAME = "event.count";
     private final Logger logger = LoggerFactory.getLogger(EventCountMetric.class);
     private static final Tag CORE_EVENT_COUNT_METRIC_TAG = Tag.of("metric", "openhab.core.metric.eventcount");
     private static final String TOPIC_TAG_NAME = "topic";

bundles/org.openhab.core.io.monitor/src/main/java/org/openhab/core/io/monitor/internal/metrics/RuleMetric.java

@@ -12,6 +12,7 @@
  */
 package org.openhab.core.io.monitor.internal.metrics;
 
+import java.time.Duration;
 import java.util.Collection;
 import java.util.HashSet;
 import java.util.Set;
@@ -22,26 +23,32 @@
 import org.openhab.core.automation.RuleRegistry;
 import org.openhab.core.automation.RuleStatus;
 import org.openhab.core.automation.events.RuleStatusInfoEvent;
+import org.openhab.core.cache.ExpiringCacheMap;
 import org.openhab.core.events.Event;
 import org.openhab.core.events.EventSubscriber;
 import org.osgi.framework.BundleContext;
 import org.osgi.framework.ServiceRegistration;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import io.micrometer.core.instrument.Counter;
 import io.micrometer.core.instrument.Meter;
 import io.micrometer.core.instrument.MeterRegistry;
 import io.micrometer.core.instrument.Tag;
+import io.micrometer.core.instrument.Timer;
 
 /**
- * The {@link RuleMetric} class implements a gauge metric for rules RUNNING events (per rule)
+ * The {@link RuleMetric} class implements a gauge metric for rules RUNNING events
+ * and for rule duration (per rule)
  *
  * @author Robert Bach - Initial contribution
+ * @author Robert Delbrück - Added Rule duration metric
  */
 @NonNullByDefault
 public class RuleMetric implements OpenhabCoreMeterBinder, EventSubscriber {
 
     public static final String METRIC_NAME = "openhab.rule.runs";
+    public static final String METRIC_DURATION_NAME = "openhab.rule.duration";
     public static final String RULES_TOPIC_PREFIX = "openhab/rules/";
     public static final String RULES_TOPIC_SUFFIX = "/state";
     private final Logger logger = LoggerFactory.getLogger(RuleMetric.class);
@@ -51,8 +58,9 @@ public class RuleMetric implements OpenhabCoreMeterBinder, EventSubscriber {
     private @Nullable MeterRegistry meterRegistry;
     private final Set<Tag> tags = new HashSet<>();
     private @Nullable ServiceRegistration<?> eventSubscriberRegistration;
-    private BundleContext bundleContext;
-    private RuleRegistry ruleRegistry;
+    private final BundleContext bundleContext;
+    private final RuleRegistry ruleRegistry;
+    private final ExpiringCacheMap<String, Timer.Sample> cache = new ExpiringCacheMap<>(Duration.ofMinutes(5));
 
     public RuleMetric(BundleContext bundleContext, Collection<Tag> tags, RuleRegistry ruleRegistry) {
         this.tags.addAll(tags);
@@ -104,19 +112,42 @@ public void receive(Event event) {
 
         String topic = event.getTopic();
         String ruleId = topic.substring(RULES_TOPIC_PREFIX.length(), topic.lastIndexOf(RULES_TOPIC_SUFFIX));
-        if (!event.getPayload().contains(RuleStatus.RUNNING.name())) {
-            logger.trace("Skipping rule status info with status other than RUNNING {}", event.getPayload());
-            return;
+        String ruleStatus = event.getPayload();
+
+        Set<Tag> tagsWithRule = createTags(ruleId);
+
+        if (ruleStatus.contains(RuleStatus.RUNNING.name())) {
+            logger.debug("Rule {} RUNNING - updating metric.", ruleId);
+            Counter.builder(METRIC_NAME).description("Execution count of the rules").tags(tagsWithRule)
+                    .register(this.meterRegistry).increment();
+            Timer.Sample start = Timer.start(meterRegistry);
+            cache.put(topic, () -> start);
+        } else if (ruleStatus.contains(RuleStatus.IDLE.name())) {
+            if (cache.containsKey(topic)) {
+                Timer.Sample sample = cache.get(topic);
+                Timer timer = Timer.builder(METRIC_DURATION_NAME).description("Execution duration of the rules")
+                        .tags(tagsWithRule).register(meterRegistry);
+                if (sample != null) {
+                    long duration = sample.stop(timer);
+                    logger.debug("Rule {} Finished - updating duration metric ({}ns).", ruleId, duration);
+                }
+            } else {
+                logger.trace("Rule {} Finished - but running state missed.", ruleId);
+            }
+            cache.remove(topic);
+        } else {
+            logger.trace("Skipping rule status info with status {}", ruleStatus);
         }
+    }
 
-        logger.debug("Rule {} RUNNING - updating metric.", ruleId);
+    private @NonNullByDefault Set<Tag> createTags(String ruleId) {
         Set<Tag> tagsWithRule = new HashSet<>(tags);
         tagsWithRule.add(Tag.of(RULE_ID_TAG_NAME, ruleId));
         String ruleName = getRuleName(ruleId);
         if (ruleName != null) {
             tagsWithRule.add(Tag.of(RULE_NAME_TAG_NAME, ruleName));
         }
-        meterRegistry.counter(METRIC_NAME, tagsWithRule).increment();
+        return tagsWithRule;
     }
 
     private @Nullable String getRuleName(String ruleId) {

bundles/org.openhab.core.io.monitor/src/test/java/org/openhab/core/io/monitor/internal/metrics/RuleMetricTest.java

@@ -0,0 +1,95 @@
+/*
+ * Copyright (c) 2010-2026 Contributors to the openHAB project
+ *
+ * See the NOTICE file(s) distributed with this work for additional
+ * information.
+ *
+ * This program and the accompanying materials are made available under the
+ * terms of the Eclipse Public License 2.0 which is available at
+ * http://www.eclipse.org/legal/epl-2.0
+ *
+ * SPDX-License-Identifier: EPL-2.0
+ */
+package org.openhab.core.io.monitor.internal.metrics;
+
+import static org.mockito.Mockito.mock;
+import static org.openhab.core.io.monitor.internal.metrics.RuleMetric.*;
+
+import java.time.Duration;
+import java.util.List;
+import java.util.concurrent.TimeUnit;
+
+import org.eclipse.jdt.annotation.NonNullByDefault;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.ExtendWith;
+import org.mockito.junit.jupiter.MockitoExtension;
+import org.openhab.core.automation.RuleRegistry;
+import org.openhab.core.automation.RuleStatus;
+import org.openhab.core.automation.RuleStatusInfo;
+import org.openhab.core.automation.events.RuleStatusInfoEvent;
+import org.osgi.framework.BundleContext;
+
+import io.micrometer.core.instrument.Meter;
+import io.micrometer.core.instrument.MockClock;
+import io.micrometer.core.instrument.Timer;
+import io.micrometer.core.instrument.simple.SimpleConfig;
+import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
+
+/**
+ * Tests for RuleMetric class
+ *
+ * @author Robert Delbrück - Initial contribution
+ */
+@ExtendWith(MockitoExtension.class)
+class RuleMetricTest {
+
+    public static final String RULE1 = "any";
+    public static final String RULE2 = "anything-else";
+
+    @Test
+    void testRuleExecution() {
+        MockClock clock = new MockClock();
+        SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry(SimpleConfig.DEFAULT, clock);
+
+        RuleMetric ruleMetric = new RuleMetric(mock(BundleContext.class), List.of(), mock(RuleRegistry.class));
+        ruleMetric.bindTo(meterRegistry);
+        fireRule(ruleMetric, clock, RULE1);
+        assertMeters(meterRegistry, 1);
+        assertMeter(meterRegistry, RULE1, 1, 1);
+
+        fireRule(ruleMetric, clock, RULE2);
+        assertMeters(meterRegistry, 2);
+        assertMeter(meterRegistry, RULE2, 1, 1);
+
+        // fire again, use the same metric
+        fireRule(ruleMetric, clock, RULE2);
+        assertMeters(meterRegistry, 2);
+        assertMeter(meterRegistry, RULE2, 2, 2);
+    }
+
+    private static void fireRule(RuleMetric ruleMetric, MockClock clock, String ruleName) {
+        ruleMetric.receive(new RuleStatusInfoEvent(RULES_TOPIC_PREFIX + ruleName + RULES_TOPIC_SUFFIX,
+                RuleStatus.RUNNING.name(), ruleName, mock(RuleStatusInfo.class), ruleName));
+        clock.add(Duration.ofSeconds(1));
+        ruleMetric.receive(new RuleStatusInfoEvent(RULES_TOPIC_PREFIX + ruleName + RULES_TOPIC_SUFFIX,
+                RuleStatus.IDLE.name(), ruleName, mock(RuleStatusInfo.class), ruleName));
+    }
+
+    private static void assertMeter(SimpleMeterRegistry meterRegistry, String ruleName, int count, int totalTime) {
+        var meter = getMeters(meterRegistry).stream().filter(m -> ruleName.equals(m.getId().getTag("rule")))
+                .map(m -> (Timer) m).findFirst().orElseThrow();
+        Assertions.assertEquals(count, meter.count());
+        Assertions.assertTrue(meter.totalTime(TimeUnit.SECONDS) >= totalTime);
+    }
+
+    private static void assertMeters(SimpleMeterRegistry meterRegistry, int size) {
+        List<Meter> durationMeters = getMeters(meterRegistry);
+        Assertions.assertEquals(size, durationMeters.size());
+    }
+
+    private static @NonNullByDefault List<Meter> getMeters(SimpleMeterRegistry meterRegistry) {
+        List<Meter> meters = meterRegistry.getMeters();
+        return meters.stream().filter(m -> m.getId().getName().equals(METRIC_DURATION_NAME)).toList();
+    }
+}