Skip to content

Commit

Permalink
Support ZGC Cycles MXBean (#2795)
Browse files Browse the repository at this point in the history
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
  • Loading branch information
shakuzen authored Sep 27, 2021
1 parent 5e93459 commit e722ce3
Show file tree
Hide file tree
Showing 2 changed files with 61 additions and 5 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,8 @@ static Optional<MemoryPoolMXBean> 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) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;

/**
Expand All @@ -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");
Expand All @@ -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);
Expand All @@ -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();
}
Expand Down

0 comments on commit e722ce3

Please sign in to comment.