--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/test/jdk/jdk/jfr/event/gc/collection/GCEventAll.java Tue May 15 20:24:34 2018 +0200
@@ -0,0 +1,530 @@
+/*
+ * Copyright (c) 2013, 2018, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation. Oracle designates this
+ * particular file as subject to the "Classpath" exception as provided
+ * by Oracle in the LICENSE file that accompanied this code.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+package jdk.jfr.event.gc.collection;
+
+import java.lang.management.ManagementFactory;
+import java.time.Duration;
+import java.time.Instant;
+import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.HashSet;
+import java.util.List;
+import java.util.Random;
+import java.util.Set;
+import java.util.stream.Collectors;
+
+import jdk.jfr.EventType;
+import jdk.jfr.FlightRecorder;
+import jdk.jfr.Recording;
+import jdk.jfr.consumer.RecordedEvent;
+import jdk.test.lib.Asserts;
+import jdk.test.lib.jfr.EventNames;
+import jdk.test.lib.jfr.Events;
+import jdk.test.lib.jfr.GCHelper;
+
+/**
+ * Tests for event garbage_collection.
+ * The test function is called from TestGCEvent*.java, with different worker threads.
+ * Groups all events belonging to the same garbage collection (the same gcId).
+ * The group of events belonging to the same GC is called a batch.
+ *
+ * This class contains the verifications done and the worker threads used to generate GCs.
+ * The helper logic are in class GCHelper.
+ *
+ * Summary of verifications:
+ * All gcIds in garbage_collection event are unique.
+ *
+ * All events in batch has the same gcId.
+ *
+ * Number of garbage_collection events == GarbageCollectionMXBean.getCollectionCount()
+ *
+ * garbage_collection.sum_pause_time approximately equals GarbageCollectionMXBean.getCollectionTime()
+ *
+ * Batch contains expected events depending on garbage_collection.name
+ *
+ * garbage_collection_start.timestamp == garbage_collection.startTime.
+ *
+ * garbage_collection.timestamp >= timestamp for all other events in batch.
+ *
+ * The start_garbage_collection and garbage_collection events must be synchronized.
+ * This means that there may be multiple start_garbage_collection before a garbage_collection,
+ * but garbage_collection.gcId must be equal to latest start_garbage_collection.gcId.
+ *
+ * start_garbage_collection must be the first event in the batch,
+ * that means no event with same gcId before garbage_collection_start event.
+ *
+ * garbage_collection.name matches what is expected by the collectors specified in initial_configuration.
+ *
+ * Duration for event "vm/gc/phases/pause" >= 1. Duration for phase level events >= 0.
+ *
+ *
+ */
+public class GCEventAll {
+ private String youngCollector = null;
+ private String oldCollector = null;
+
+ /**
+ * Trigger GC events by generating garbage and calling System.gc() concurrently.
+ */
+ public static void doTest() throws Throwable {
+ // Trigger GC events by generating garbage and calling System.gc() concurrently.
+ Thread[] workerThreads = new Thread[] {
+ new Thread(GCEventAll.GarbageRunner.create(10)),
+ new Thread(GCEventAll.SystemGcWaitRunner.create(10, 2, 1000))};
+ GCEventAll test = new GCEventAll();
+ test.doSingleTest(workerThreads);
+ }
+
+ /**
+ * Runs the test once with given worker threads.
+ * @param workerThreads Threads that generates GCs.
+ * @param gcIds Set of all used gcIds
+ * @throws Exception
+ */
+ private void doSingleTest(Thread[] workerThreads) throws Throwable {
+ Recording recording = new Recording();
+ enableAllGcEvents(recording);
+
+ // Start with a full GC to minimize risk of getting extra GC between
+ // getBeanCollectionCount() and recording.start().
+ doSystemGc();
+ GCHelper.CollectionSummary startBeanCount = GCHelper.CollectionSummary.createFromMxBeans();
+ recording.start();
+
+ for (Thread t : workerThreads) {
+ t.start();
+ }
+ for (Thread t : workerThreads) {
+ t.join();
+ }
+
+ // End with a full GC to minimize risk of getting extra GC between
+ // recording.stop and getBeanCollectionCount().
+ doSystemGc();
+ // Add an extra System.gc() to make sure we get at least one full garbage_collection batch at
+ // the end of the test. This extra System.gc() is only necessary when using "UseConcMarkSweepGC" and "+ExplicitGCInvokesConcurrent".
+ doSystemGc();
+
+ recording.stop();
+ GCHelper.CollectionSummary deltaBeanCount = GCHelper.CollectionSummary.createFromMxBeans();
+ deltaBeanCount = deltaBeanCount.calcDelta(startBeanCount);
+
+ List<RecordedEvent> events = Events.fromRecording(recording).stream()
+ .filter(evt -> EventNames.isGcEvent(evt.getEventType()))
+ .collect(Collectors.toList());
+ RecordedEvent configEvent = GCHelper.getConfigEvent(events);
+ youngCollector = Events.assertField(configEvent, "youngCollector").notEmpty().getValue();
+ oldCollector = Events.assertField(configEvent, "oldCollector").notEmpty().getValue();
+ verify(events, deltaBeanCount);
+ }
+
+ private void enableAllGcEvents(Recording recording) {
+ FlightRecorder flightrecorder = FlightRecorder.getFlightRecorder();
+ for (EventType et : flightrecorder.getEventTypes()) {
+ if (EventNames.isGcEvent(et)) {
+ recording.enable(et.getName());
+ System.out.println("Enabled GC event: " + et.getName());
+ }
+ }
+ System.out.println("All GC events enabled");
+ }
+
+ private static synchronized void doSystemGc() {
+ System.gc();
+ }
+
+ /**
+ * Does all verifications of the received events.
+ *
+ * @param events All flight recorder events.
+ * @param beanCounts Number of collections and sum pause time reported by GarbageCollectionMXBeans.
+ * @param gcIds All used gcIds. Must be unique.
+ * @throws Exception
+ */
+ private void verify(List<RecordedEvent> events, GCHelper.CollectionSummary beanCounts) throws Throwable {
+ List<GCHelper.GcBatch> gcBatches = null;
+ GCHelper.CollectionSummary eventCounts = null;
+
+ // For some GC configurations, the JFR recording may have stopped before we received the last gc event.
+ try {
+ events = filterIncompleteGcBatch(events);
+ gcBatches = GCHelper.GcBatch.createFromEvents(events);
+ eventCounts = GCHelper.CollectionSummary.createFromEvents(gcBatches);
+
+ verifyUniqueIds(gcBatches);
+ verifyCollectorNames(gcBatches);
+ verifyCollectionCause(gcBatches);
+ verifyCollectionCount(eventCounts, beanCounts);
+ verifyPhaseEvents(gcBatches);
+ verifySingleGcBatch(gcBatches);
+ } catch (Throwable t) {
+ log(events, gcBatches, eventCounts, beanCounts);
+ if (gcBatches != null) {
+ for (GCHelper.GcBatch batch : gcBatches) {
+ System.out.println(String.format("Batch:%n%s", batch.getLog()));
+ }
+ }
+ throw t;
+ }
+ }
+
+ /**
+ * When using collector ConcurrentMarkSweep with -XX:+ExplicitGCInvokesConcurrent, the JFR recording may
+ * stop before we have received the last garbage_collection event.
+ *
+ * This function does 3 things:
+ * 1. Check if the last batch is incomplete.
+ * 2. If it is incomplete, then asserts that incomplete batches are allowed for this configuration.
+ * 3. If incomplete batches are allowed, then the incomplete batch is removed.
+ *
+ * @param events All events
+ * @return All events with any incomplete batch removed.
+ * @throws Throwable
+ */
+ private List<RecordedEvent> filterIncompleteGcBatch(List<RecordedEvent> events) throws Throwable {
+ List<RecordedEvent> returnEvents = new ArrayList<RecordedEvent>(events);
+ int lastGcId = getLastGcId(events);
+ List<RecordedEvent> lastBatchEvents = getEventsWithGcId(events, lastGcId);
+ String[] endEvents = {GCHelper.event_garbage_collection, GCHelper.event_old_garbage_collection, GCHelper.event_young_garbage_collection};
+ boolean isComplete = containsAnyPath(lastBatchEvents, endEvents);
+ if (!isComplete) {
+ // The last GC batch does not contain an end event. The batch is incomplete.
+ // This is only allowed if we are using old_collector="ConcurrentMarkSweep" and "-XX:+ExplicitGCInvokesConcurrent"
+ boolean isExplicitGCInvokesConcurrent = hasInputArgument("-XX:+ExplicitGCInvokesConcurrent");
+ boolean isConcurrentMarkSweep = GCHelper.gcConcurrentMarkSweep.equals(oldCollector);
+ String msg = String.format(
+ "Incomplete batch only allowed for '%s' with -XX:+ExplicitGCInvokesConcurrent",
+ GCHelper.gcConcurrentMarkSweep);
+ Asserts.assertTrue(isConcurrentMarkSweep && isExplicitGCInvokesConcurrent, msg);
+
+ // Incomplete batch is allowed with the current settings. Remove incomplete batch.
+ returnEvents.removeAll(lastBatchEvents);
+ }
+ return returnEvents;
+ }
+
+ private boolean hasInputArgument(String arg) {
+ return ManagementFactory.getRuntimeMXBean().getInputArguments().contains(arg);
+ }
+
+ private List<RecordedEvent> getEventsWithGcId(List<RecordedEvent> events, int gcId) {
+ List<RecordedEvent> batchEvents = new ArrayList<>();
+ for (RecordedEvent event : events) {
+ if (GCHelper.isGcEvent(event) && GCHelper.getGcId(event) == gcId) {
+ batchEvents.add(event);
+ }
+ }
+ return batchEvents;
+ }
+
+ private boolean containsAnyPath(List<RecordedEvent> events, String[] paths) {
+ List<String> pathList = Arrays.asList(paths);
+ for (RecordedEvent event : events) {
+ if (pathList.contains(event.getEventType().getName())) {
+ return true;
+ }
+ }
+ return false;
+ }
+
+ private int getLastGcId(List<RecordedEvent> events) {
+ int lastGcId = -1;
+ for (RecordedEvent event : events) {
+ if (GCHelper.isGcEvent(event)) {
+ int gcId = GCHelper.getGcId(event);
+ if (gcId > lastGcId) {
+ lastGcId = gcId;
+ }
+ }
+ }
+ Asserts.assertTrue(lastGcId != -1, "No gcId found");
+ return lastGcId;
+ }
+
+ /**
+ * Verifies collection count reported by flight recorder events against the values
+ * reported by GarbageCollectionMXBean.
+ * Number of collections should match exactly.
+ * Sum pause time are allowed some margin of error because of rounding errors in measurements.
+ */
+ private void verifyCollectionCount(GCHelper.CollectionSummary eventCounts, GCHelper.CollectionSummary beanCounts) {
+ verifyCollectionCount(youngCollector, eventCounts.collectionCountYoung, beanCounts.collectionCountYoung);
+ verifyCollectionCount(oldCollector, eventCounts.collectionCountOld, beanCounts.collectionCountOld);
+ }
+
+ private void verifyCollectionCount(String collector, long eventCounts, long beanCounts) {
+ if (GCHelper.gcConcurrentMarkSweep.equals(collector) || GCHelper.gcG1Old.equals(oldCollector)) {
+ // ConcurrentMarkSweep mixes old and new collections. Not same values as in MXBean.
+ // MXBean does not report old collections for G1Old, so we have nothing to compare with.
+ return;
+ }
+ // JFR events and GarbageCollectorMXBean events are not updated at the same time.
+ // This means that number of collections may diff.
+ // We allow a diff of +- 1 collection count.
+ long minCount = Math.max(0, beanCounts - 1);
+ long maxCount = beanCounts + 1;
+ Asserts.assertGreaterThanOrEqual(eventCounts, minCount, "Too few event counts for collector " + collector);
+ Asserts.assertLessThanOrEqual(eventCounts, maxCount, "Too many event counts for collector " + collector);
+ }
+
+ /**
+ * Verifies that all events belonging to a single GC are ok.
+ * A GcBatch contains all flight recorder events that belong to a single GC.
+ */
+ private void verifySingleGcBatch(List<GCHelper.GcBatch> batches) {
+ for (GCHelper.GcBatch batch : batches) {
+ //System.out.println("batch:\r\n" + batch.getLog());
+ try {
+ RecordedEvent endEvent = batch.getEndEvent();
+ Asserts.assertNotNull(endEvent, "No end event in batch.");
+ Asserts.assertNotNull(batch.getName(), "No method name in end event.");
+ long longestPause = Events.assertField(endEvent, "longestPause").atLeast(0L).getValue();
+ Events.assertField(endEvent, "sumOfPauses").atLeast(longestPause).getValue();
+ Instant batchStartTime = endEvent.getStartTime();
+ Instant batchEndTime = endEvent.getEndTime();
+ for (RecordedEvent event : batch.getEvents()) {
+ if (event.getEventType().getName().contains("AllocationRequiringGC")) {
+ // Unlike other events, these are sent *before* a GC.
+ Asserts.assertLessThanOrEqual(event.getStartTime(), batchStartTime, "Timestamp in event after start event, should be sent before GC start");
+ } else {
+ Asserts.assertGreaterThanOrEqual(event.getStartTime(), batchStartTime, "startTime in event before batch start event, should be sent after GC start");
+ }
+ Asserts.assertLessThanOrEqual(event.getEndTime(), batchEndTime, "endTime in event after batch end event, should be sent before GC end");
+ }
+
+ // Verify that all required events has been received.
+ String[] requiredEvents = GCHelper.requiredEvents.get(batch.getName());
+ Asserts.assertNotNull(requiredEvents, "No required events specified for " + batch.getName());
+ for (String requiredEvent : requiredEvents) {
+ boolean b = batch.containsEvent(requiredEvent);
+ Asserts.assertTrue(b, String.format("%s does not contain event %s", batch, requiredEvent));
+ }
+
+ // Verify that we have exactly one heap_summary "Before GC" and one "After GC".
+ int countBeforeGc = 0;
+ int countAfterGc = 0;
+ for (RecordedEvent event : batch.getEvents()) {
+ if (GCHelper.event_heap_summary.equals(event.getEventType().getName())) {
+ String when = Events.assertField(event, "when").notEmpty().getValue();
+ if ("Before GC".equals(when)) {
+ countBeforeGc++;
+ } else if ("After GC".equals(when)) {
+ countAfterGc++;
+ } else {
+ Asserts.fail("Unknown value for heap_summary.when: '" + when + "'");
+ }
+ }
+ }
+ if (!GCHelper.gcConcurrentMarkSweep.equals(batch.getName())) {
+ // We do not get heap_summary events for ConcurrentMarkSweep
+ Asserts.assertEquals(1, countBeforeGc, "Unexpected number of heap_summary.before_gc");
+ Asserts.assertEquals(1, countAfterGc, "Unexpected number of heap_summary.after_gc");
+ }
+ } catch (Throwable e) {
+ GCHelper.log("verifySingleGcBatch failed for gcEvent:");
+ GCHelper.log(batch.getLog());
+ throw e;
+ }
+ }
+ }
+
+ private Set<Integer> verifyUniqueIds(List<GCHelper.GcBatch> batches) {
+ Set<Integer> gcIds = new HashSet<>();
+ for (GCHelper.GcBatch batch : batches) {
+ Integer gcId = new Integer(batch.getGcId());
+ Asserts.assertFalse(gcIds.contains(gcId), "Duplicate gcId: " + gcId);
+ gcIds.add(gcId);
+ }
+ return gcIds;
+ }
+
+ private void verifyPhaseEvents(List<GCHelper.GcBatch> batches) {
+ for (GCHelper.GcBatch batch : batches) {
+ for(RecordedEvent event : batch.getEvents()) {
+ if (event.getEventType().getName().contains(GCHelper.pauseLevelEvent)) {
+ Instant batchStartTime = batch.getEndEvent().getStartTime();
+ Asserts.assertGreaterThanOrEqual(
+ event.getStartTime(), batchStartTime, "Phase startTime >= batch startTime. Event:" + event);
+
+ // Duration for event "vm/gc/phases/pause" must be >= 1. Other phase event durations must be >= 0.
+ Duration minDuration = Duration.ofNanos(GCHelper.event_phases_pause.equals(event.getEventType().getName()) ? 1 : 0);
+ Duration duration = event.getDuration();
+ Asserts.assertGreaterThanOrEqual(duration, minDuration, "Wrong duration. Event:" + event);
+ }
+ }
+ }
+ }
+
+ /**
+ * Verifies that the collector name in initial configuration matches the name in garbage configuration event.
+ * If the names are not equal, then we check if this is an expected collector override.
+ * For example, if old collector in initial config is "G1Old" we allow both event "G1Old" and "SerialOld".
+ */
+ private void verifyCollectorNames(List<GCHelper.GcBatch> batches) {
+ for (GCHelper.GcBatch batch : batches) {
+ String name = batch.getName();
+ Asserts.assertNotNull(name, "garbage_collection.name was null");
+ boolean isYoung = batch.isYoungCollection();
+ String expectedName = isYoung ? youngCollector : oldCollector;
+ if (!expectedName.equals(name)) {
+ // Collector names not equal. Check if the collector has been overridden by an expected collector.
+ String overrideKey = expectedName + "." + name;
+ boolean isOverride = GCHelper.collectorOverrides.contains(overrideKey);
+ Asserts.assertTrue(isOverride, String.format("Unexpected event name(%s) for collectors(%s, %s)", name, youngCollector, oldCollector));
+ }
+ }
+ }
+
+ /**
+ * Verifies field "cause" in garbage_collection event.
+ * Only check that at cause is not null and that at least 1 cause is "System.gc()"
+ * We might want to check more cause reasons later.
+ */
+ private void verifyCollectionCause(List<GCHelper.GcBatch> batches) {
+ int systemGcCount = 0;
+ for (GCHelper.GcBatch batch : batches) {
+ RecordedEvent endEvent = batch.getEndEvent();
+ String cause = Events.assertField(endEvent, "cause").notEmpty().getValue();
+ // A System.GC() can be consolidated into a GCLocker GC
+ if (cause.equals("System.gc()") || cause.equals("GCLocker Initiated GC")) {
+ systemGcCount++;
+ }
+ Asserts.assertNotNull(batch.getName(), "garbage_collection.name was null");
+ }
+ final String msg = "No event with cause=System.gc(), collectors(%s, %s)";
+ Asserts.assertTrue(systemGcCount > 0, String.format(msg, youngCollector, oldCollector));
+ }
+
+ private void log(List<RecordedEvent> events, List<GCHelper.GcBatch> batches,
+ GCHelper.CollectionSummary eventCounts, GCHelper.CollectionSummary beanCounts) {
+ GCHelper.log("EventCounts:");
+ if (eventCounts != null) {
+ GCHelper.log(eventCounts.toString());
+ }
+ GCHelper.log("BeanCounts:");
+ if (beanCounts != null) {
+ GCHelper.log(beanCounts.toString());
+ }
+ }
+
+ /**
+ * Thread that does a number of System.gc().
+ */
+ public static class SystemGcRunner implements Runnable {
+ private final int totalCollections;
+
+ public SystemGcRunner(int totalCollections) {
+ this.totalCollections = totalCollections;
+ }
+
+ public static SystemGcRunner create(int totalCollections) {
+ return new SystemGcRunner(totalCollections);
+ }
+
+ public void run() {
+ for (int i = 0; i < totalCollections; i++) {
+ GCEventAll.doSystemGc();
+ }
+ }
+ }
+
+ /**
+ * Thread that creates garbage until a certain number of GCs has been run.
+ */
+ public static class GarbageRunner implements Runnable {
+ private final int totalCollections;
+ public byte[] dummyBuffer = null;
+
+ public GarbageRunner(int totalCollections) {
+ this.totalCollections = totalCollections;
+ }
+
+ public static GarbageRunner create(int totalCollections) {
+ return new GarbageRunner(totalCollections);
+ }
+
+ public void run() {
+ long currCollections = GCHelper.CollectionSummary.createFromMxBeans().sum();
+ long endCollections = totalCollections + currCollections;
+ Random r = new Random(0);
+ while (true) {
+ for (int i = 0; i < 1000; i++) {
+ dummyBuffer = new byte[r.nextInt(10000)];
+ }
+ if (GCHelper.CollectionSummary.createFromMxBeans().sum() >= endCollections) {
+ break;
+ }
+ }
+ }
+ }
+
+ /**
+ * Thread that runs System.gc() and then wait for a number of GCs or a maximum time.
+ */
+ public static class SystemGcWaitRunner implements Runnable {
+ private final int totalCollections;
+ private final int minWaitCollections;
+ private final long maxWaitMillis;
+
+ public SystemGcWaitRunner(int totalCollections, int minWaitCollections, long maxWaitMillis) {
+ this.totalCollections = totalCollections;
+ this.minWaitCollections = minWaitCollections;
+ this.maxWaitMillis = maxWaitMillis;
+ }
+
+ public static SystemGcWaitRunner create(int deltaCollections, int minWaitCollections, long maxWaitMillis) {
+ return new SystemGcWaitRunner(deltaCollections, minWaitCollections, maxWaitMillis);
+ }
+
+ public void run() {
+ long currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();
+ long endCount = totalCollections + currCount;
+ long nextSystemGcCount = currCount + minWaitCollections;
+ long now = System.currentTimeMillis();
+ long nextSystemGcMillis = now + maxWaitMillis;
+
+ while (true) {
+ if (currCount >= nextSystemGcCount || System.currentTimeMillis() > nextSystemGcMillis) {
+ GCEventAll.doSystemGc();
+ currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();
+ nextSystemGcCount = currCount + minWaitCollections;
+ } else {
+ try {
+ Thread.sleep(20);
+ } catch (InterruptedException e) {
+ e.printStackTrace();
+ break;
+ }
+ }
+ currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();
+ if (currCount >= endCount) {
+ break;
+ }
+ }
+ }
+ }
+
+}