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 }