JVM Garbage collection metrics

4 files changed, 163 insertions, 2 deletions

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..49353332271
--- /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.util.HashMap;
+import java.util.Iterator;
+import java.util.LinkedList;
+import java.util.Map;
+
+/**
+ * @author ollivir
+ */
+public class GarbageCollectionMetrics {
+    private static final String GC_PREFIX = "jdisc.gc.";
+    private static final String GC_COUNT = GC_PREFIX + ".count";
+    private static final String GC_TIME = GC_PREFIX + ".ms";
+    private static final String DIMENSION_KEY = "gcName";
+
+    public static final long REPORTING_INTERVAL = Duration.ofSeconds(62).toMillis();
+
+    static class GcStats {
+        private final long when;
+        private final long count;
+        private final long ms;
+
+        private GcStats(long when, long count, long ms) {
+            this.when = when;
+            this.count = count;
+            this.ms = ms;
+        }
+    }
+
+    private Map<String, LinkedList<GcStats>> gcStatistics;
+
+    private final Clock clock;
+
+    public GarbageCollectionMetrics(Clock clock) {
+        this.clock = clock;
+        this.gcStatistics = new HashMap<>();
+        collectGcStatistics(clock.millis());
+    }
+
+    private void collectGcStatistics(long now) {
+        for (GarbageCollectorMXBean gcBean : ManagementFactory.getGarbageCollectorMXBeans()) {
+            String gcName = gcBean.getName().replace(" ", "");
+            GcStats stats = new GcStats(now, gcBean.getCollectionCount(), gcBean.getCollectionTime());
+
+            LinkedList<GcStats> window = gcStatistics.computeIfAbsent(gcName, anyName -> new LinkedList<>());
+            window.addLast(stats);
+        }
+    }
+
+    private void cleanStatistics(long now) {
+        long oldestToKeep = now - 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 && history.getFirst().when < oldestToKeep) {
+                history.removeFirst();
+            }
+            if(history.isEmpty()) {
+                it.remove();
+            }
+        }
+    }
+
+    public void emitMetrics(Metric metric) {
+        long now = clock.millis();
+
+        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.ms - reference.ms, 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..76ad430f4b9
--- /dev/null
+++ b/container-disc/src/test/java/com/yahoo/container/jdisc/metric/GarbageCollectionMetricsTest.java
@@ -0,0 +1,60 @@
+package com.yahoo.container.jdisc.metric;
+
+import com.yahoo.jdisc.Metric;
+import org.junit.Test;
+
+import java.lang.management.ManagementFactory;
+import java.time.Clock;
+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.atLeast;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.never;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
+
+/**
+ * @author ollivir
+ */
+public class GarbageCollectionMetricsTest {
+    @Test
+    public void gc_metrics_reported_at_intervals() {
+        Clock clock = mock(Clock.class);
+        Metric metric = mock(Metric.class);
+        int base = ManagementFactory.getGarbageCollectorMXBeans().size();
+
+        long iv = GarbageCollectionMetrics.REPORTING_INTERVAL;
+        when(clock.millis()).thenReturn(10L);
+        GarbageCollectionMetrics garbageCollectionMetrics = new GarbageCollectionMetrics(clock);
+        assertThat(garbageCollectionMetrics.getGcStatistics().keySet().size(), is(base));
+
+        when(clock.millis()).thenReturn(iv);
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 2);
+
+        when(clock.millis()).thenReturn(10L + iv);
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 3);
+
+        when(clock.millis()).thenReturn(20L + iv);
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 3);
+
+        when(clock.millis()).thenReturn(20L + iv + iv);
+        garbageCollectionMetrics.emitMetrics(metric);
+        assertWindowLengths(garbageCollectionMetrics, 2);
+
+        verify(metric, times(base * 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 {