Merge pull request #6054 from vespa-engine/ovirtanen/jdisc-garbage-collection-metrics

Jdisc garbage collection metrics

5 files changed, 167 insertions, 2 deletions

diff --git a/config-model/src/main/java/com/yahoo/vespa/model/admin/monitoring/VespaMetricSet.java b/config-model/src/main/java/com/yahoo/vespa/model/admin/monitoring/VespaMetricSet.java
index 6467199d9f9..fc46ed18dde 100644
--- a/config-model/src/main/java/com/yahoo/vespa/model/admin/monitoring/VespaMetricSet.java
+++ b/config-model/src/main/java/com/yahoo/vespa/model/admin/monitoring/VespaMetricSet.java
@@ -110,6 +110,13 @@ public class VespaMetricSet {
         metrics.add(new Metric("jdisc.memory_mappings.max"));
         metrics.add(new Metric("jdisc.open_file_descriptors.max"));
 
+        metrics.add(new Metric("jdisc.gc.count.average"));
+        metrics.add(new Metric("jdisc.gc.count.max"));
+        metrics.add(new Metric("jdisc.gc.count.last"));
+        metrics.add(new Metric("jdisc.gc.ms.average"));
+        metrics.add(new Metric("jdisc.gc.ms.max"));
+        metrics.add(new Metric("jdisc.gc.ms.last"));
+
         metrics.add(new Metric("jdisc.deactivated_containers.total.last"));
         metrics.add(new Metric("jdisc.deactivated_containers.with_retained_refs.last"));
 
diff --git a/container-disc/src/main/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetrics.java b/container-disc/src/main/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetrics.java
new file mode 100644
index 00000000000..04fd8572ad4
--- /dev/null
+++ b/container-disc/src/main/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetrics.java
@@ -0,0 +1,94 @@
+package com.yahoo.container.jdisc.metric;
+
+import com.yahoo.jdisc.Metric;
+
+import java.lang.management.GarbageCollectorMXBean;
+import java.lang.management.ManagementFactory;
+import java.time.Clock;
+import java.time.Duration;
+import java.time.Instant;
+import java.util.HashMap;
+import java.util.Iterator;
+import java.util.LinkedList;
+import java.util.Map;
+
+/**
+ * @author ollivir
+ */
+public class GarbageCollectionMetrics {
+    private static final String GC_COUNT = "jdisc.gc.count";
+    private static final String GC_TIME = "jdisc.gc.ms";
+    private static final String DIMENSION_KEY = "gcName";
+
+    public static final Duration REPORTING_INTERVAL = Duration.ofSeconds(62);
+
+    static class GcStats {
+        private final Instant when;
+        private final long count;
+        private final Duration totalRuntime;
+
+        private GcStats(Instant when, long count, Duration totalRuntime) {
+            this.when = when;
+            this.count = count;
+            this.totalRuntime = totalRuntime;
+        }
+    }
+
+    private Map<String, LinkedList<GcStats>> gcStatistics;
+
+    private final Clock clock;
+
+    public GarbageCollectionMetrics(Clock clock) {
+        this.clock = clock;
+        this.gcStatistics = new HashMap<>();
+        collectGcStatistics(clock.instant());
+    }
+
+    private void collectGcStatistics(Instant now) {
+        for (GarbageCollectorMXBean gcBean : ManagementFactory.getGarbageCollectorMXBeans()) {
+            String gcName = gcBean.getName().replace(" ", "");
+            GcStats stats = new GcStats(now, gcBean.getCollectionCount(), Duration.ofMillis(gcBean.getCollectionTime()));
+
+            LinkedList<GcStats> window = gcStatistics.computeIfAbsent(gcName, anyName -> new LinkedList<>());
+            window.addLast(stats);
+        }
+    }
+
+    private void cleanStatistics(Instant now) {
+        Instant oldestToKeep = now.minus(REPORTING_INTERVAL);
+
+        for(Iterator<Map.Entry<String, LinkedList<GcStats>>> it = gcStatistics.entrySet().iterator(); it.hasNext(); ) {
+            Map.Entry<String, LinkedList<GcStats>> entry = it.next();
+            LinkedList<GcStats> history = entry.getValue();
+            while(history.isEmpty() == false && oldestToKeep.isAfter(history.getFirst().when)) {
+                history.removeFirst();
+            }
+            if(history.isEmpty()) {
+                it.remove();
+            }
+        }
+    }
+
+    public void emitMetrics(Metric metric) {
+        Instant now = clock.instant();
+
+        collectGcStatistics(now);
+        cleanStatistics(now);
+
+        for (Map.Entry<String, LinkedList<GcStats>> item : gcStatistics.entrySet()) {
+            GcStats reference = item.getValue().getFirst();
+            GcStats latest = item.getValue().getLast();
+            Map<String, String> contextData = new HashMap<>();
+            contextData.put(DIMENSION_KEY, item.getKey());
+            Metric.Context gcContext = metric.createContext(contextData);
+
+            metric.set(GC_COUNT, latest.count - reference.count, gcContext);
+            metric.set(GC_TIME, latest.totalRuntime.minus(reference.totalRuntime).toMillis(), gcContext);
+        }
+    }
+
+    // partial exposure for testing
+    Map<String, LinkedList<GcStats>> getGcStatistics() {
+        return gcStatistics;
+    }
+}
diff --git a/container-disc/src/main/java/com/yahoo/container/jdisc/metric/MetricUpdater.java b/container-disc/src/main/java/com/yahoo/container/jdisc/metric/MetricUpdater.java
index 22b049c9ab7..c2ef789e8fc 100644
--- a/container-disc/src/main/java/com/yahoo/container/jdisc/metric/MetricUpdater.java
+++ b/container-disc/src/main/java/com/yahoo/container/jdisc/metric/MetricUpdater.java
@@ -10,6 +10,7 @@ import java.nio.file.DirectoryStream;
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.nio.file.Paths;
+import java.time.Clock;
 import java.time.Duration;
 import java.util.Timer;
 import java.util.TimerTask;
@@ -89,10 +90,12 @@ public class MetricUpdater extends AbstractComponent {
         private final Runtime runtime = Runtime.getRuntime();
         private final Metric metric;
         private final ContainerWatchdogMetrics containerWatchdogMetrics;
+        private final GarbageCollectionMetrics garbageCollectionMetrics;
 
         public UpdaterTask(Metric metric, ContainerWatchdogMetrics containerWatchdogMetrics) {
             this.metric = metric;
             this.containerWatchdogMetrics = containerWatchdogMetrics;
+            this.garbageCollectionMetrics = new GarbageCollectionMetrics(Clock.systemUTC());
         }
 
         @SuppressWarnings("deprecation")
@@ -109,9 +112,10 @@ public class MetricUpdater extends AbstractComponent {
             metric.set(TOTAL_MEMORY_BYTES, totalMemory, null);
             metric.set(MEMORY_MAPPINGS_COUNT, count_mappings(), null);
             metric.set(OPEN_FILE_DESCRIPTORS, count_open_files(), null);
+
             containerWatchdogMetrics.emitMetrics(metric);
+            garbageCollectionMetrics.emitMetrics(metric);
         }
-
     }
 
     private static class TimerScheduler implements Scheduler {
diff --git a/container-disc/src/test/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetricsTest.java b/container-disc/src/test/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetricsTest.java
new file mode 100644
index 00000000000..61d8763b852
--- /dev/null
+++ b/container-disc/src/test/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetricsTest.java
@@ -0,0 +1,57 @@
+package com.yahoo.container.jdisc.metric;
+
+import com.yahoo.jdisc.Metric;
+import com.yahoo.test.ManualClock;
+import org.junit.Test;
+
+import java.lang.management.ManagementFactory;
+import java.time.Duration;
+import java.util.LinkedList;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.is;
+import static org.mockito.Matchers.any;
+import static org.mockito.Matchers.anyString;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+
+/**
+ * @author ollivir
+ */
+public class GarbageCollectionMetricsTest {
+    @Test
+    public void gc_metrics_are_collected_in_a_sliding_window() {
+        ManualClock clock = new ManualClock();
+        Metric metric = mock(Metric.class);
+        int garbageCollectors = ManagementFactory.getGarbageCollectorMXBeans().size();
+
+        Duration interval = GarbageCollectionMetrics.REPORTING_INTERVAL;
+        GarbageCollectionMetrics garbageCollectionMetrics = new GarbageCollectionMetrics(clock);
+        assertThat(garbageCollectionMetrics.getGcStatistics().keySet().size(), is(garbageCollectors));
+
+        clock.advance(interval.minus(Duration.ofMillis(10)));
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 2);
+
+        clock.advance(Duration.ofMillis(10));
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 3);
+
+        clock.advance(Duration.ofMillis(10));
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 3);
+
+        clock.advance(interval);
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 2);
+
+        verify(metric, times(garbageCollectors * 4 * 2)).set(anyString(), any(), any());
+    }
+
+    private static void assertWindowLengths(GarbageCollectionMetrics gcm, int count) {
+        for(LinkedList<GarbageCollectionMetrics.GcStats> window: gcm.getGcStatistics().values()) {
+            assertThat(window.size(), is(count));
+        }
+    }
+}
diff --git a/container-disc/src/test/java/com/yahoo/container/jdisc/metric/MetricUpdaterTest.java b/container-disc/src/test/java/com/yahoo/container/jdisc/metric/MetricUpdaterTest.java
index f10af7593a4..e9e04eab3b4 100644
--- a/container-disc/src/test/java/com/yahoo/container/jdisc/metric/MetricUpdaterTest.java
+++ b/container-disc/src/test/java/com/yahoo/container/jdisc/metric/MetricUpdaterTest.java
@@ -5,6 +5,7 @@ import com.yahoo.jdisc.Metric;
 import com.yahoo.jdisc.statistics.ContainerWatchdogMetrics;
 import org.junit.Test;
 
+import java.lang.management.ManagementFactory;
 import java.time.Duration;
 
 import static org.mockito.Matchers.any;
@@ -20,11 +21,13 @@ public class MetricUpdaterTest {
     
     @Test
     public void metrics_are_updated_in_scheduler_cycle() throws InterruptedException {
+        int gcCount = ManagementFactory.getGarbageCollectorMXBeans().size();
+
         Metric metric = mock(Metric.class);
         ContainerWatchdogMetrics containerWatchdogMetrics = mock(ContainerWatchdogMetrics.class);
         new MetricUpdater(new MockScheduler(), metric, containerWatchdogMetrics);
         verify(containerWatchdogMetrics, times(1)).emitMetrics(any());
-        verify(metric, times(8)).set(anyString(), any(), any());
+        verify(metric, times(8 + 2 * gcCount)).set(anyString(), any(), any());
     }
 
     private static class MockScheduler implements MetricUpdater.Scheduler {