1 /*

     2  * Copyright (c) 2013, 2018, Oracle and/or its affiliates. All rights reserved.

     3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.

     4  *

     5  * This code is free software; you can redistribute it and/or modify it

     6  * under the terms of the GNU General Public License version 2 only, as

     7  * published by the Free Software Foundation.  Oracle designates this

     8  * particular file as subject to the "Classpath" exception as provided

     9  * by Oracle in the LICENSE file that accompanied this code.

    10  *

    11  * This code is distributed in the hope that it will be useful, but WITHOUT

    12  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or

    13  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License

    14  * version 2 for more details (a copy is included in the LICENSE file that

    15  * accompanied this code).

    16  *

    17  * You should have received a copy of the GNU General Public License version

    18  * 2 along with this work; if not, write to the Free Software Foundation,

    19  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.

    20  *

    21  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA

    22  * or visit www.oracle.com if you need additional information or have any

    23  * questions.

    24  */

    25 

    26 package jdk.jfr.event.gc.collection;

    27 

    28 import java.lang.management.ManagementFactory;

    29 import java.time.Duration;

    30 import java.time.Instant;

    31 import java.util.ArrayList;

    32 import java.util.Arrays;

    33 import java.util.HashSet;

    34 import java.util.List;

    35 import java.util.Random;

    36 import java.util.Set;

    37 import java.util.stream.Collectors;

    38 

    39 import jdk.jfr.EventType;

    40 import jdk.jfr.FlightRecorder;

    41 import jdk.jfr.Recording;

    42 import jdk.jfr.consumer.RecordedEvent;

    43 import jdk.test.lib.Asserts;

    44 import jdk.test.lib.jfr.EventNames;

    45 import jdk.test.lib.jfr.Events;

    46 import jdk.test.lib.jfr.GCHelper;

    47 

    48 /**

    49  * Tests for event garbage_collection.

    50  * The test function is called from TestGCEvent*.java, with different worker threads.

    51  * Groups all events belonging to the same garbage collection (the same gcId).

    52  * The group of events belonging to the same GC is called a batch.

    53  *

    54  * This class contains the verifications done and the worker threads used to generate GCs.

    55  * The helper logic are in class GCHelper.

    56  *

    57  * Summary of verifications:

    58  *   All gcIds in garbage_collection event are unique.

    59  *

    60  *   All events in batch has the same gcId.

    61  *

    62  *   Number of garbage_collection events == GarbageCollectionMXBean.getCollectionCount()

    63  *

    64  *   garbage_collection.sum_pause_time approximately equals GarbageCollectionMXBean.getCollectionTime()

    65  *

    66  *   Batch contains expected events depending on garbage_collection.name

    67  *

    68  *   garbage_collection_start.timestamp == garbage_collection.startTime.

    69  *

    70  *   garbage_collection.timestamp >= timestamp for all other events in batch.

    71  *

    72  *   The start_garbage_collection and garbage_collection events must be synchronized.

    73  *     This means that there may be multiple start_garbage_collection before a garbage_collection,

    74  *     but garbage_collection.gcId must be equal to latest start_garbage_collection.gcId.

    75  *

    76  *   start_garbage_collection must be the first event in the batch,

    77  *     that means no event with same gcId before garbage_collection_start event.

    78  *

    79  *   garbage_collection.name matches what is expected by the collectors specified in initial_configuration.

    80  *

    81  *   Duration for event "vm/gc/phases/pause" >= 1. Duration for phase level events >= 0.

    82  *

    83  *

    84  */

    85 public class GCEventAll {

    86     private String youngCollector = null;

    87     private String oldCollector = null;

    88 

    89     /**

    90      *  Trigger GC events by generating garbage and calling System.gc() concurrently.

    91      */

    92     public static void doTest() throws Throwable {

    93         // Trigger GC events by generating garbage and calling System.gc() concurrently.

    94         Thread[] workerThreads = new Thread[] {

    95                 new Thread(GCEventAll.GarbageRunner.create(10)),

    96                 new Thread(GCEventAll.SystemGcWaitRunner.create(10, 2, 1000))};

    97         GCEventAll test = new GCEventAll();

    98         test.doSingleTest(workerThreads);

    99     }

   100 

   101     /**

   102      * Runs the test once with given worker threads.

   103      * @param workerThreads Threads that generates GCs.

   104      * @param gcIds Set of all used gcIds

   105      * @throws Exception

   106      */

   107     private void doSingleTest(Thread[] workerThreads) throws Throwable {

   108         Recording recording = new Recording();

   109         enableAllGcEvents(recording);

   110 

   111         // Start with a full GC to minimize risk of getting extra GC between

   112         // getBeanCollectionCount() and recording.start().

   113         doSystemGc();

   114         GCHelper.CollectionSummary startBeanCount = GCHelper.CollectionSummary.createFromMxBeans();

   115         recording.start();

   116 

   117         for (Thread t : workerThreads) {

   118             t.start();

   119         }

   120         for (Thread t : workerThreads) {

   121             t.join();

   122         }

   123 

   124         // End with a full GC to minimize risk of getting extra GC between

   125         // recording.stop and getBeanCollectionCount().

   126         doSystemGc();

   127         // Add an extra System.gc() to make sure we get at least one full garbage_collection batch at

   128         // the end of the test. This extra System.gc() is only necessary when using "UseConcMarkSweepGC" and "+ExplicitGCInvokesConcurrent".

   129         doSystemGc();

   130 

   131         recording.stop();

   132         GCHelper.CollectionSummary deltaBeanCount = GCHelper.CollectionSummary.createFromMxBeans();

   133         deltaBeanCount = deltaBeanCount.calcDelta(startBeanCount);

   134 

   135         List<RecordedEvent> events = Events.fromRecording(recording).stream()

   136             .filter(evt -> EventNames.isGcEvent(evt.getEventType()))

   137             .collect(Collectors.toList());

   138         RecordedEvent configEvent = GCHelper.getConfigEvent(events);

   139         youngCollector = Events.assertField(configEvent, "youngCollector").notEmpty().getValue();

   140         oldCollector = Events.assertField(configEvent, "oldCollector").notEmpty().getValue();

   141         verify(events, deltaBeanCount);

   142     }

   143 

   144     private void enableAllGcEvents(Recording recording) {

   145         FlightRecorder flightrecorder = FlightRecorder.getFlightRecorder();

   146         for (EventType et : flightrecorder.getEventTypes()) {

   147             if (EventNames.isGcEvent(et)) {

   148                 recording.enable(et.getName());

   149                 System.out.println("Enabled GC event: " + et.getName());

   150             }

   151         }

   152         System.out.println("All GC events enabled");

   153     }

   154 

   155     private static synchronized void doSystemGc() {

   156         System.gc();

   157     }

   158 

   159     /**

   160      * Does all verifications of the received events.

   161      *

   162      * @param events All flight recorder events.

   163      * @param beanCounts Number of collections and sum pause time reported by GarbageCollectionMXBeans.

   164      * @param gcIds All used gcIds. Must be unique.

   165      * @throws Exception

   166      */

   167     private void verify(List<RecordedEvent> events, GCHelper.CollectionSummary beanCounts) throws Throwable {

   168         List<GCHelper.GcBatch> gcBatches = null;

   169         GCHelper.CollectionSummary eventCounts = null;

   170 

   171         // For some GC configurations, the JFR recording may have stopped before we received the last gc event.

   172         try {

   173             events = filterIncompleteGcBatch(events);

   174             gcBatches = GCHelper.GcBatch.createFromEvents(events);

   175             eventCounts = GCHelper.CollectionSummary.createFromEvents(gcBatches);

   176 

   177             verifyUniqueIds(gcBatches);

   178             verifyCollectorNames(gcBatches);

   179             verifyCollectionCause(gcBatches);

   180             verifyCollectionCount(eventCounts, beanCounts);

   181             verifyPhaseEvents(gcBatches);

   182             verifySingleGcBatch(gcBatches);

   183         } catch (Throwable t) {

   184             log(events, gcBatches, eventCounts, beanCounts);

   185             if (gcBatches != null) {

   186                 for (GCHelper.GcBatch batch : gcBatches) {

   187                     System.out.println(String.format("Batch:%n%s", batch.getLog()));

   188                 }

   189             }

   190             throw t;

   191         }

   192     }

   193 

   194     /**

   195      * When using collector ConcurrentMarkSweep with -XX:+ExplicitGCInvokesConcurrent, the JFR recording may

   196      * stop before we have received the last garbage_collection event.

   197      *

   198      * This function does 3 things:

   199      * 1. Check if the last batch is incomplete.

   200      * 2. If it is incomplete, then asserts that incomplete batches are allowed for this configuration.

   201      * 3. If incomplete batches are allowed, then the incomplete batch is removed.

   202      *

   203      * @param events All events

   204      * @return All events with any incomplete batch removed.

   205      * @throws Throwable

   206      */

   207     private List<RecordedEvent> filterIncompleteGcBatch(List<RecordedEvent> events) throws Throwable {

   208         List<RecordedEvent> returnEvents = new ArrayList<RecordedEvent>(events);

   209         int lastGcId = getLastGcId(events);

   210         List<RecordedEvent> lastBatchEvents = getEventsWithGcId(events, lastGcId);

   211         String[] endEvents = {GCHelper.event_garbage_collection, GCHelper.event_old_garbage_collection, GCHelper.event_young_garbage_collection};

   212         boolean isComplete = containsAnyPath(lastBatchEvents, endEvents);

   213         if (!isComplete) {

   214             // The last GC batch does not contain an end event. The batch is incomplete.

   215             // This is only allowed if we are using old_collector="ConcurrentMarkSweep" and "-XX:+ExplicitGCInvokesConcurrent"

   216             boolean isExplicitGCInvokesConcurrent = hasInputArgument("-XX:+ExplicitGCInvokesConcurrent");

   217             boolean isConcurrentMarkSweep = GCHelper.gcConcurrentMarkSweep.equals(oldCollector);

   218             String msg = String.format(

   219                     "Incomplete batch only allowed for '%s' with -XX:+ExplicitGCInvokesConcurrent",

   220                     GCHelper.gcConcurrentMarkSweep);

   221             Asserts.assertTrue(isConcurrentMarkSweep && isExplicitGCInvokesConcurrent, msg);

   222 

   223             // Incomplete batch is allowed with the current settings. Remove incomplete batch.

   224             returnEvents.removeAll(lastBatchEvents);

   225         }

   226         return returnEvents;

   227     }

   228 

   229     private boolean hasInputArgument(String arg) {

   230         return ManagementFactory.getRuntimeMXBean().getInputArguments().contains(arg);

   231     }

   232 

   233     private List<RecordedEvent> getEventsWithGcId(List<RecordedEvent> events, int gcId) {

   234         List<RecordedEvent> batchEvents = new ArrayList<>();

   235         for (RecordedEvent event : events) {

   236             if (GCHelper.isGcEvent(event) && GCHelper.getGcId(event) == gcId) {

   237                 batchEvents.add(event);

   238             }

   239         }

   240         return batchEvents;

   241     }

   242 

   243     private boolean containsAnyPath(List<RecordedEvent> events, String[] paths) {

   244         List<String> pathList = Arrays.asList(paths);

   245         for (RecordedEvent event : events) {

   246             if (pathList.contains(event.getEventType().getName())) {

   247                 return true;

   248             }

   249         }

   250         return false;

   251     }

   252 

   253     private int getLastGcId(List<RecordedEvent> events) {

   254         int lastGcId = -1;

   255         for (RecordedEvent event : events) {

   256             if (GCHelper.isGcEvent(event)) {

   257                 int gcId = GCHelper.getGcId(event);

   258                 if (gcId > lastGcId) {

   259                     lastGcId = gcId;

   260                 }

   261             }

   262         }

   263         Asserts.assertTrue(lastGcId != -1, "No gcId found");

   264         return lastGcId;

   265     }

   266 

   267     /**

   268      * Verifies collection count reported by flight recorder events against the values

   269      * reported by GarbageCollectionMXBean.

   270      * Number of collections should match exactly.

   271      * Sum pause time are allowed some margin of error because of rounding errors in measurements.

   272      */

   273     private void verifyCollectionCount(GCHelper.CollectionSummary eventCounts, GCHelper.CollectionSummary beanCounts) {

   274         verifyCollectionCount(youngCollector, eventCounts.collectionCountYoung, beanCounts.collectionCountYoung);

   275         verifyCollectionCount(oldCollector, eventCounts.collectionCountOld, beanCounts.collectionCountOld);

   276     }

   277 

   278     private void verifyCollectionCount(String collector, long eventCounts, long beanCounts) {

   279         if (GCHelper.gcConcurrentMarkSweep.equals(collector) || GCHelper.gcG1Old.equals(oldCollector)) {

   280             // ConcurrentMarkSweep mixes old and new collections. Not same values as in MXBean.

   281             // MXBean does not report old collections for G1Old, so we have nothing to compare with.

   282             return;

   283         }

   284         // JFR events and GarbageCollectorMXBean events are not updated at the same time.

   285         // This means that number of collections may diff.

   286         // We allow a diff of +- 1 collection count.

   287         long minCount = Math.max(0, beanCounts - 1);

   288         long maxCount = beanCounts + 1;

   289         Asserts.assertGreaterThanOrEqual(eventCounts, minCount, "Too few event counts for collector " + collector);

   290         Asserts.assertLessThanOrEqual(eventCounts, maxCount, "Too many event counts for collector " + collector);

   291     }

   292 

   293     /**

   294      * Verifies that all events belonging to a single GC are ok.

   295      * A GcBatch contains all flight recorder events that belong to a single GC.

   296      */

   297     private void verifySingleGcBatch(List<GCHelper.GcBatch> batches) {

   298         for (GCHelper.GcBatch batch : batches) {

   299             //System.out.println("batch:\r\n" + batch.getLog());

   300             try {

   301                 RecordedEvent endEvent = batch.getEndEvent();

   302                 Asserts.assertNotNull(endEvent, "No end event in batch.");

   303                 Asserts.assertNotNull(batch.getName(), "No method name in end event.");

   304                 long longestPause = Events.assertField(endEvent, "longestPause").atLeast(0L).getValue();

   305                 Events.assertField(endEvent, "sumOfPauses").atLeast(longestPause).getValue();

   306                 Instant batchStartTime = endEvent.getStartTime();

   307                 Instant batchEndTime = endEvent.getEndTime();

   308                 for (RecordedEvent event : batch.getEvents()) {

   309                     if (event.getEventType().getName().contains("AllocationRequiringGC")) {

   310                         // Unlike other events, these are sent *before* a GC.

   311                         Asserts.assertLessThanOrEqual(event.getStartTime(), batchStartTime, "Timestamp in event after start event, should be sent before GC start");

   312                     } else {

   313                         Asserts.assertGreaterThanOrEqual(event.getStartTime(), batchStartTime, "startTime in event before batch start event, should be sent after GC start");

   314                     }

   315                     Asserts.assertLessThanOrEqual(event.getEndTime(), batchEndTime, "endTime in event after batch end event, should be sent before GC end");

   316                 }

   317 

   318                 // Verify that all required events has been received.

   319                 String[] requiredEvents = GCHelper.requiredEvents.get(batch.getName());

   320                 Asserts.assertNotNull(requiredEvents, "No required events specified for " + batch.getName());

   321                 for (String requiredEvent : requiredEvents) {

   322                     boolean b = batch.containsEvent(requiredEvent);

   323                     Asserts.assertTrue(b, String.format("%s does not contain event %s", batch, requiredEvent));

   324                 }

   325 

   326                 // Verify that we have exactly one heap_summary "Before GC" and one "After GC".

   327                 int countBeforeGc = 0;

   328                 int countAfterGc = 0;

   329                 for (RecordedEvent event : batch.getEvents()) {

   330                     if (GCHelper.event_heap_summary.equals(event.getEventType().getName())) {

   331                         String when = Events.assertField(event, "when").notEmpty().getValue();

   332                         if ("Before GC".equals(when)) {

   333                             countBeforeGc++;

   334                         } else if ("After GC".equals(when)) {

   335                             countAfterGc++;

   336                         } else {

   337                             Asserts.fail("Unknown value for heap_summary.when: '" + when + "'");

   338                         }

   339                     }

   340                 }

   341                 if (!GCHelper.gcConcurrentMarkSweep.equals(batch.getName())) {

   342                     // We do not get heap_summary events for ConcurrentMarkSweep

   343                     Asserts.assertEquals(1, countBeforeGc, "Unexpected number of heap_summary.before_gc");

   344                     Asserts.assertEquals(1, countAfterGc, "Unexpected number of heap_summary.after_gc");

   345                 }

   346             } catch (Throwable e) {

   347                 GCHelper.log("verifySingleGcBatch failed for gcEvent:");

   348                 GCHelper.log(batch.getLog());

   349                 throw e;

   350             }

   351         }

   352     }

   353 

   354     private Set<Integer> verifyUniqueIds(List<GCHelper.GcBatch> batches) {

   355         Set<Integer> gcIds = new HashSet<>();

   356         for (GCHelper.GcBatch batch : batches) {

   357             Integer gcId = new Integer(batch.getGcId());

   358             Asserts.assertFalse(gcIds.contains(gcId), "Duplicate gcId: " + gcId);

   359             gcIds.add(gcId);

   360         }

   361         return gcIds;

   362     }

   363 

   364     private void verifyPhaseEvents(List<GCHelper.GcBatch> batches) {

   365         for (GCHelper.GcBatch batch : batches) {

   366             for(RecordedEvent event : batch.getEvents()) {

   367                 if (event.getEventType().getName().contains(GCHelper.pauseLevelEvent)) {

   368                     Instant batchStartTime = batch.getEndEvent().getStartTime();

   369                     Asserts.assertGreaterThanOrEqual(

   370                         event.getStartTime(), batchStartTime, "Phase startTime >= batch startTime. Event:" + event);

   371 

   372                     // Duration for event "vm/gc/phases/pause" must be >= 1. Other phase event durations must be >= 0.

   373                     Duration minDuration = Duration.ofNanos(GCHelper.event_phases_pause.equals(event.getEventType().getName()) ? 1 : 0);

   374                     Duration duration = event.getDuration();

   375                     Asserts.assertGreaterThanOrEqual(duration, minDuration, "Wrong duration. Event:" + event);

   376                 }

   377             }

   378         }

   379     }

   380 

   381     /**

   382      * Verifies that the collector name in initial configuration matches the name in garbage configuration event.

   383      * If the names are not equal, then we check if this is an expected collector override.

   384      * For example, if old collector in initial config is "G1Old" we allow both event "G1Old" and "SerialOld".

   385      */

   386     private void verifyCollectorNames(List<GCHelper.GcBatch> batches) {

   387         for (GCHelper.GcBatch batch : batches) {

   388             String name = batch.getName();

   389             Asserts.assertNotNull(name, "garbage_collection.name was null");

   390             boolean isYoung = batch.isYoungCollection();

   391             String expectedName = isYoung ? youngCollector : oldCollector;

   392             if (!expectedName.equals(name)) {

   393                 // Collector names not equal. Check if the collector has been overridden by an expected collector.

   394                 String overrideKey = expectedName + "." + name;

   395                 boolean isOverride = GCHelper.collectorOverrides.contains(overrideKey);

   396                 Asserts.assertTrue(isOverride, String.format("Unexpected event name(%s) for collectors(%s, %s)", name, youngCollector, oldCollector));

   397             }

   398         }

   399     }

   400 

   401     /**

   402      * Verifies field "cause" in garbage_collection event.

   403      * Only check that at cause is not null and that at least 1 cause is "System.gc()"

   404      * We might want to check more cause reasons later.

   405      */

   406     private void verifyCollectionCause(List<GCHelper.GcBatch> batches) {

   407         int systemGcCount = 0;

   408         for (GCHelper.GcBatch batch : batches) {

   409             RecordedEvent endEvent = batch.getEndEvent();

   410             String cause = Events.assertField(endEvent, "cause").notEmpty().getValue();

   411             // A System.GC() can be consolidated into a GCLocker GC

   412             if (cause.equals("System.gc()") || cause.equals("GCLocker Initiated GC")) {

   413                 systemGcCount++;

   414             }

   415             Asserts.assertNotNull(batch.getName(), "garbage_collection.name was null");

   416         }

   417         final String msg = "No event with cause=System.gc(), collectors(%s, %s)";

   418         Asserts.assertTrue(systemGcCount > 0, String.format(msg, youngCollector, oldCollector));

   419     }

   420 

   421     private void log(List<RecordedEvent> events, List<GCHelper.GcBatch> batches,

   422         GCHelper.CollectionSummary eventCounts, GCHelper.CollectionSummary beanCounts) {

   423         GCHelper.log("EventCounts:");

   424         if (eventCounts != null) {

   425             GCHelper.log(eventCounts.toString());

   426         }

   427         GCHelper.log("BeanCounts:");

   428         if (beanCounts != null) {

   429             GCHelper.log(beanCounts.toString());

   430         }

   431     }

   432 

   433     /**

   434      * Thread that does a number of System.gc().

   435      */

   436     public static class SystemGcRunner implements Runnable {

   437         private final int totalCollections;

   438 

   439         public SystemGcRunner(int totalCollections) {

   440             this.totalCollections = totalCollections;

   441         }

   442 

   443         public static SystemGcRunner create(int totalCollections) {

   444             return new SystemGcRunner(totalCollections);

   445         }

   446 

   447         public void run() {

   448             for (int i = 0; i < totalCollections; i++) {

   449                 GCEventAll.doSystemGc();

   450             }

   451         }

   452     }

   453 

   454     /**

   455      * Thread that creates garbage until a certain number of GCs has been run.

   456      */

   457     public static class GarbageRunner implements Runnable {

   458         private final int totalCollections;

   459         public byte[] dummyBuffer = null;

   460 

   461         public GarbageRunner(int totalCollections) {

   462             this.totalCollections = totalCollections;

   463         }

   464 

   465         public static GarbageRunner create(int totalCollections) {

   466             return new GarbageRunner(totalCollections);

   467         }

   468 

   469         public void run() {

   470             long currCollections = GCHelper.CollectionSummary.createFromMxBeans().sum();

   471             long endCollections = totalCollections + currCollections;

   472             Random r = new Random(0);

   473             while (true) {

   474                 for (int i = 0; i < 1000; i++) {

   475                     dummyBuffer = new byte[r.nextInt(10000)];

   476                 }

   477                 if (GCHelper.CollectionSummary.createFromMxBeans().sum() >= endCollections) {

   478                     break;

   479                 }

   480             }

   481         }

   482     }

   483 

   484     /**

   485      * Thread that runs System.gc() and then wait for a number of GCs or a maximum time.

   486      */

   487     public static class SystemGcWaitRunner implements Runnable {

   488         private final int totalCollections;

   489         private final int minWaitCollections;

   490         private final long maxWaitMillis;

   491 

   492         public SystemGcWaitRunner(int totalCollections, int minWaitCollections, long maxWaitMillis) {

   493             this.totalCollections = totalCollections;

   494             this.minWaitCollections = minWaitCollections;

   495             this.maxWaitMillis = maxWaitMillis;

   496         }

   497 

   498         public static SystemGcWaitRunner create(int deltaCollections, int minWaitCollections, long maxWaitMillis) {

   499             return new SystemGcWaitRunner(deltaCollections, minWaitCollections, maxWaitMillis);

   500         }

   501 

   502         public void run() {

   503             long currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();

   504             long endCount = totalCollections + currCount;

   505             long nextSystemGcCount = currCount + minWaitCollections;

   506             long now = System.currentTimeMillis();

   507             long nextSystemGcMillis = now + maxWaitMillis;

   508 

   509             while (true) {

   510                 if (currCount >= nextSystemGcCount || System.currentTimeMillis() > nextSystemGcMillis) {

   511                     GCEventAll.doSystemGc();

   512                     currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();

   513                     nextSystemGcCount = currCount + minWaitCollections;

   514                 } else {

   515                     try {

   516                         Thread.sleep(20);

   517                     } catch (InterruptedException e) {

   518                         e.printStackTrace();

   519                         break;

   520                     }

   521                 }

   522                 currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();

   523                 if (currCount >= endCount) {

   524                     break;

   525                 }

   526             }

   527         }

   528     }

   529 

   530 }