From e722ce37e3b6659567b1a0a9677f87f88a231fe1 Mon Sep 17 00:00:00 2001 From: Tommy Ludwig <8924140+shakuzen@users.noreply.github.com> Date: Tue, 28 Sep 2021 04:29:17 +0900 Subject: [PATCH] Support ZGC Cycles MXBean (#2795) Since Java 17, the GarbageCollectorMXBean for ZGC has been split into `ZGC Pauses` and `ZGC Cycles`, which allows us to properly measure the pause time and the concurrent collection time. Before we only had access to the overall time. Resolves gh-2372 --- .../core/instrument/binder/jvm/JvmMemory.java | 3 +- .../binder/jvm/JvmGcMetricsTest.java | 63 +++++++++++++++++-- 2 files changed, 61 insertions(+), 5 deletions(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/jvm/JvmMemory.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/jvm/JvmMemory.java index 44339b8b3f..0cb6f777cd 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/jvm/JvmMemory.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/jvm/JvmMemory.java @@ -40,7 +40,8 @@ static Optional getLongLivedHeapPool() { static boolean isConcurrentPhase(String cause, String name) { return "No GC".equals(cause) - || "Shenandoah Cycles".equals(name); + || "Shenandoah Cycles".equals(name) + || "ZGC Cycles".equals(name); } static boolean isAllocationPool(String name) { diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/jvm/JvmGcMetricsTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/jvm/JvmGcMetricsTest.java index 45d34e2ba9..3c05b4fa77 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/jvm/JvmGcMetricsTest.java +++ b/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/jvm/JvmGcMetricsTest.java @@ -19,14 +19,22 @@ import com.tngtech.archunit.core.domain.JavaClasses; import com.tngtech.archunit.core.importer.ClassFileImporter; import com.tngtech.archunit.lang.ArchRule; +import io.micrometer.core.instrument.Timer; import io.micrometer.core.instrument.simple.SimpleMeterRegistry; -import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.*; +import org.junit.jupiter.api.condition.EnabledForJreRange; +import org.junit.jupiter.api.condition.JRE; +import java.lang.management.GarbageCollectorMXBean; +import java.lang.management.ManagementFactory; import java.lang.management.MemoryPoolMXBean; +import java.util.concurrent.TimeUnit; import static com.tngtech.archunit.core.domain.JavaClass.Predicates.resideInAPackage; import static com.tngtech.archunit.lang.syntax.ArchRuleDefinition.methods; import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.within; +import static org.awaitility.Awaitility.await; import static org.junit.jupiter.api.Assumptions.assumeTrue; /** @@ -37,6 +45,13 @@ @GcTest class JvmGcMetricsTest { + SimpleMeterRegistry registry = new SimpleMeterRegistry(); + + @BeforeEach + void beforeEach() { + new JvmGcMetrics().bindTo(registry); + } + @Test void noJvmImplementationSpecificApiSignatures() { JavaClasses importedClasses = new ClassFileImporter().importPackages("io.micrometer.core.instrument.binder.jvm"); @@ -50,9 +65,6 @@ void noJvmImplementationSpecificApiSignatures() { @Test void metersAreBound() { - SimpleMeterRegistry registry = new SimpleMeterRegistry(); - JvmGcMetrics binder = new JvmGcMetrics(); - binder.bindTo(registry); assertThat(registry.find("jvm.gc.live.data.size").gauge()).isNotNull(); assertThat(registry.find("jvm.gc.memory.allocated").counter()).isNotNull(); assertThat(registry.find("jvm.gc.max.data.size").gauge().value()).isGreaterThan(0); @@ -61,6 +73,49 @@ void metersAreBound() { assertThat(registry.find("jvm.gc.memory.promoted").counter()).isNotNull(); } + @Test + @Disabled("Garbage collection can happen before JvmGcMetrics are registered, making our metrics not match overall counts/timings") + // available for some platforms and distributions earlier, but broadest availability in an LTS is 17 + @EnabledForJreRange(min = JRE.JAVA_17) + void gcTimingIsCorrect() { + System.gc(); + long pausePhaseCount = 0; + long pauseTimeMs = 0; + long concurrentPhaseCount = 0; + long concurrentTimeMs = 0; + for (GarbageCollectorMXBean mbean : ManagementFactory.getGarbageCollectorMXBeans()) { + if (mbean.getName().contains("Pauses")) { + pausePhaseCount += mbean.getCollectionCount(); + pauseTimeMs += mbean.getCollectionTime(); + } else if (mbean.getName().contains("Cycles")) { + concurrentPhaseCount += mbean.getCollectionCount(); + concurrentTimeMs += mbean.getCollectionTime(); + } + System.out.println(mbean.getName() + " (" + mbean.getCollectionCount() + ") " + mbean.getCollectionTime() + "ms"); + } + checkPhaseCount(pausePhaseCount, concurrentPhaseCount); + checkCollectionTime(pauseTimeMs, concurrentTimeMs); + } + + private void checkPhaseCount(long expectedPauseCount, long expectedConcurrentCount) { + await().atMost(200, TimeUnit.MILLISECONDS).untilAsserted(() -> { + long observedPauseCount = registry.find("jvm.gc.pause").timers().stream().mapToLong(Timer::count).sum(); + long observedConcurrentCount = registry.find("jvm.gc.concurrent.phase.time").timers().stream().mapToLong(Timer::count).sum(); + assertThat(observedPauseCount).isEqualTo(expectedPauseCount); + assertThat(observedConcurrentCount).isEqualTo(expectedConcurrentCount); + }); + } + + private void checkCollectionTime(long expectedPauseTimeMs, long expectedConcurrentTimeMs) { + await().atMost(200, TimeUnit.MILLISECONDS).untilAsserted(() -> { + double observedPauseTimeMs = registry.find("jvm.gc.pause").timers().stream().mapToDouble(timer -> timer.totalTime(TimeUnit.MILLISECONDS)).sum(); + double observedConcurrentTimeMs = registry.find("jvm.gc.concurrent.phase.time").timers().stream().mapToDouble(timer -> timer.totalTime(TimeUnit.MILLISECONDS)).sum(); + // small difference can happen when less than 1ms timing gets rounded + assertThat(observedPauseTimeMs).isCloseTo(expectedPauseTimeMs, within(1d)); + assertThat(observedConcurrentTimeMs).isCloseTo(expectedConcurrentTimeMs, within(1d)); + }); + } + private boolean isGenerationalGc() { return JvmMemory.getLongLivedHeapPool().map(MemoryPoolMXBean::getName).filter(JvmMemory::isOldGenPool).isPresent(); }