1 /*
2 * Copyright (c) 2013, Oracle and/or its affiliates. All rights reserved.
3 * ORACLE PROPRIETARY/CONFIDENTIAL. Use is subject to license terms.
4 */
5 import java.util.Arrays;
6 import java.util.List;
7 import java.util.ArrayList;
8 import java.util.Collections;
9 import java.util.HashSet;
10 import java.util.Iterator;
11 import java.util.Random;
12 import java.util.Set;
13
14 import jrockit.Asserts;
15 import jrockit.jfr.JFRHelper;
16 import jrockit.jfr.TestRecording;
17 import oracle.jrockit.jfr.parser.ChunkParser;
18 import oracle.jrockit.jfr.parser.FLREvent;
19 import oracle.jrockit.jfr.parser.FLRStruct;
20
21 import java.lang.management.ManagementFactory;
22 import java.lang.management.RuntimeMXBean;
23
24
25 /**
26 * Tests for event garbage_collection.
27 * The test function is called from TestGCEvent*.java, with different worker threads.
28 * Groups all events belonging to the same garbage collection (the same gcId).
29 * The group of events belonging to the same GC is called a batch.
30 *
31 * This class contains the verifications done and the worker threads used to generate GCs.
32 * The helper logic are in class GCHelper.
33 *
34 * Summary of verifications:
35 * All gcIds in garbage_collection event are unique.
36 *
37 * All events in batch has the same gcId.
38 *
39 * Number of garbage_collection events == GarbageCollectionMXBean.getCollectionCount()
40 *
41 * garbage_collection.sum_pause_time approximately equals GarbageCollectionMXBean.getCollectionTime()
42 *
43 * Batch contains expected events depending on garbage_collection.name
44 *
45 * garbage_collection_start.timestamp == garbage_collection.startTime.
46 *
47 * garbage_collection.timestamp >= timestamp for all other events in batch.
48 *
49 * The start_garbage_collection and garbage_collection events must be synchronized.
50 * This means that there may be multiple start_garbage_collection before a garbage_collection,
51 * but garbage_collection.gcId must be equal to latest start_garbage_collection.gcId.
52 *
53 * start_garbage_collection must be the first event in the batch,
54 * that means no event with same gcId before garbage_collection_start event.
55 *
56 * garbage_collection.name matches what is expected by the collectors specified in initial_configuration.
57 *
58 * Duration for event "vm/gc/phases/pause" >= 1. Duration for phase level events >= 0.
59 *
60 *
61 */
62 public class GCEventAll {
63 private static Set<Integer> gcIds = new HashSet<Integer>();
64 private static int systemGcCount = 0;
65 private boolean isIncompleteBatchRemoved = false;
66
67 private String youngCollector = null;
68 private String oldCollector = null;
69
70 /**
71 * Runs the test once with given worker threads.
72 * @param workerThreads Threads that generates GCs.
73 * @param gcIds Set of all used gcIds
74 * @throws Exception
75 */
76 public void doSingleTest(Thread[] workerThreads) throws Throwable {
77 TestRecording r = new TestRecording();
78 final String gcEventRoot = "vm/gc/*";
79 List<FLREvent> events = null;
80 try {
81 r.createJVMSetting(gcEventRoot, true, false, 0, 0);
82
83 // Start with a full GC to minimize risk of getting extra GC between
84 // getBeanCollectionCount() and recording.start().
85 doSystemGc();
86 GCHelper.CollectionSummary startBeanCount = GCHelper.CollectionSummary.createFromMxBeans();
87 systemGcCount = 0;
88 r.start();
89
90 for (Thread t : workerThreads) {
91 t.start();
92 }
93 for (Thread t : workerThreads) {
94 t.join();
95 }
96
97 // End with a full GC to minimize risk of getting extra GC between
98 // recording.stop and getBeanCollectionCount().
99 doSystemGc();
100 // Add an extra System.gc() to make sure we get at least one full garbage_collection batch at
101 // the end of the test. This extra System.gc() is only necessary when using "UseConcMarkSweepGC" and "+ExplicitGCInvokesConcurrent".
102 doSystemGc();
103
104 r.stop();
105 GCHelper.CollectionSummary deltaBeanCount = GCHelper.CollectionSummary.createFromMxBeans();
106 deltaBeanCount = deltaBeanCount.calcDelta(startBeanCount);
107 events = r.parser().findJVMEvents(gcEventRoot + ".*");
108 Collections.sort(events, new JFRHelper.EventTimestampComparator());
109 FLREvent configEvent = GCHelper.getConfigEvent(events);
110 youngCollector = (String)((FLRStruct)configEvent.getResolvedValue("youngCollector")).getValue("name");
111 oldCollector = (String)((FLRStruct)configEvent.getResolvedValue("oldCollector")).getValue("name");
112 verify(events, deltaBeanCount);
113 } catch (Throwable e) {
114 String filename = this.getClass().getSimpleName() + "-" + System.currentTimeMillis() + ".jfr";
115 r.copyTo(filename);
116 System.out.println("Failed recording saved as " + filename);
117 System.out.println("All events:");
118 for (FLREvent event : events) {
119 System.out.println(event);
120 }
121 throw e;
122 } finally {
123 r.close();
124 }
125 }
126
127 public static synchronized void doSystemGc() {
128 systemGcCount++;
129 System.gc();
130 }
131
132 /**
133 * Does all verifications of the received events.
134 *
135 * @param events All flight recorder events.
136 * @param beanCounts Number of collections and sum pause time reported by GarbageCollectionMXBeans.
137 * @param gcIds All used gcIds. Must be unique.
138 * @throws Exception
139 */
140 public void verify(List<FLREvent> events, GCHelper.CollectionSummary beanCounts) throws Throwable {
141 List<GCHelper.GcBatch> gcBatches = null;
142 GCHelper.CollectionSummary eventCounts = null;
143 Throwable firstError = null;
144
145 // For some GC configurations, the JFR recording may have stopped before we received the last gc event.
146 int oldSize = events.size();
147 events = filterIncompleteGcBatch(events);
148 if (events.size() != oldSize) {
149 isIncompleteBatchRemoved = true;
150 }
151
152 // Parse events
153 try {
154 gcBatches = GCHelper.GcBatch.createFromEvents(events);
155 eventCounts = GCHelper.CollectionSummary.createFromEvents(gcBatches);
156 } catch (Throwable t) {
157 t.printStackTrace();
158 firstError = firstError == null ? t : firstError;
159 }
160
161 // Verify events if parsing was ok.
162 if (firstError == null) {
163 try {
164 verifyUniqueIds(gcBatches, gcIds);
165 } catch (Throwable t) {
166 t.printStackTrace();
167 firstError = firstError == null ? t : firstError;
168 }
169 try {
170 verifySingleGcBatch(gcBatches);
171 } catch (Throwable t) {
172 t.printStackTrace();
173 firstError = firstError == null ? t : firstError;
174 }
175 try {
176 verifyCollectorNames(gcBatches);
177 } catch (Throwable t) {
178 t.printStackTrace();
179 firstError = firstError == null ? t : firstError;
180 }
181 try {
182 verifyCollectionCount(eventCounts, beanCounts);
183 } catch (Throwable t) {
184 t.printStackTrace();
185 firstError = firstError == null ? t : firstError;
186 }
187 try {
188 verifyCollectionCause(gcBatches);
189 } catch (Throwable t) {
190 t.printStackTrace();
191 firstError = firstError == null ? t : firstError;
192 }
193 try {
194 verifyPhaseEvents(gcBatches);
195 } catch (Throwable t) {
196 t.printStackTrace();
197 firstError = firstError == null ? t : firstError;
198 }
199 }
200
201 if (firstError != null) {
202 // At least one error found. Log all events.
203 log(events, gcBatches, eventCounts, beanCounts);
204 throw firstError;
205 }
206 }
207
208 /**
209 * When using collector ConcurrentMarkSweep with -XX:+ExplicitGCInvokesConcurrent, the JFR recording may
210 * stop before we have received the last garbage_collection event.
211 *
212 * This function does 3 things:
213 * 1. Check if the last batch is incomplete.
214 * 2. If it is incomplete, then asserts that incomplete batches are allowed for this configuration.
215 * 3. If incomplete batches are allowed, then the incomplete batch is removed.
216 *
217 * @param events All events
218 * @return All events with any incomplete batch removed.
219 * @throws Throwable
220 */
221 private List<FLREvent> filterIncompleteGcBatch(List<FLREvent> events) throws Throwable {
222 List<FLREvent> returnEvents = new ArrayList<FLREvent>();
223 returnEvents.addAll(events);
224
225 int lastGcId = getLastGcId(events);
226 List<FLREvent> lastBatchEvents = getEventsWithGcId(events, lastGcId);
227 String[] endEvents = {GCHelper.event_garbage_collection, GCHelper.event_old_garbage_collection, GCHelper.event_young_garbage_collection};
228 boolean isComplete = containsAnyPath(lastBatchEvents, endEvents);
229 if (!isComplete) {
230 // The last GC batch does not contain an end event. The batch is incomplete.
231 // This is only allowed if we are using old_collector="ConcurrentMarkSweep" and "-XX:+ExplicitGCInvokesConcurrent"
232 boolean isExplicitGCInvokesConcurrent = hasInputArgument("-XX:+ExplicitGCInvokesConcurrent");
233 boolean isConcurrentMarkSweep = GCHelper.gcConcurrentMarkSweep.equals(oldCollector);
234 String msg = String.format(
235 "Incomplete batch only allowed for '%s' with -XX:+ExplicitGCInvokesConcurrent",
236 GCHelper.gcConcurrentMarkSweep);
237 Asserts.assertTrue(isConcurrentMarkSweep && isExplicitGCInvokesConcurrent, msg);
238
239 // This batch is incomplete, but that is allowed with the current settings.
240 // Remove the incomplete batch.
241 returnEvents.removeAll(lastBatchEvents);
242 }
243 return returnEvents;
244 }
245
246 /**
247 * Checks if a given argument was specified on the command line when this program was started.
248 * @param arg The argument to search for
249 * @return true if the argument is on the command line.
250 */
251 private boolean hasInputArgument(String arg) {
252 RuntimeMXBean runtimeMxBean = ManagementFactory.getRuntimeMXBean();
253 List<String> arguments = runtimeMxBean.getInputArguments();
254 for (String currArg : arguments) {
255 if (currArg.equals(arg)) {
256 return true;
257 }
258 }
259 return false;
260 }
261
262 /**
263 * Get all events that has the specified gcId.
264 * @param events All events.
265 * @param gcId The specified gcId.
266 * @return A list of the events with the specified gcId.
267 */
268 private List<FLREvent> getEventsWithGcId(List<FLREvent> events, int gcId) {
269 List<FLREvent> batchEvents = new ArrayList<FLREvent>();
270 for (FLREvent event : events) {
271 if (GCHelper.isGcEvent(event) && GCHelper.getGcId(event) == gcId) {
272 batchEvents.add(event);
273 }
274 }
275 return batchEvents;
276 }
277
278 /**
279 * Checks if at least one event in the list has one of the specified paths.
280 * @param events All events.
281 * @param paths The paths to search for.
282 * @return true if at least one of the events has one of the specified paths.
283 */
284 private boolean containsAnyPath(List<FLREvent> events, String[] paths) {
285 Set<String> pathSet = new HashSet<String>(Arrays.asList(paths));
286 for (FLREvent event : events) {
287 if (pathSet.contains(event.getPath())) {
288 return true;
289 }
290 }
291 return false;
292 }
293
294 /**
295 * Return the highest gcId in the list.
296 * @param events All events.
297 * @return the highest gcId found in the list or -1 if no event had a gcId.
298 */
299 private int getLastGcId(List<FLREvent> events) {
300 int lastGcId = -1;
301 for (FLREvent event : events) {
302 if (GCHelper.isGcEvent(event)) {
303 int gcId = GCHelper.getGcId(event);
304 if (gcId > lastGcId) {
305 lastGcId = gcId;
306 }
307 }
308 }
309 Asserts.assertTrue(lastGcId != -1, "No gcId found");
310 return lastGcId;
311 }
312
313 /**
314 * Verifies collection count reported by flight recorder events against the values
315 * reported by GarbageCollectionMXBean.
316 * Number of collections should match exactly.
317 * Sum pause time are allowed some margin of error because of rounding errors in measurements.
318 */
319 private void verifyCollectionCount(GCHelper.CollectionSummary eventCounts, GCHelper.CollectionSummary beanCounts) {
320 verifyCollectionCount(youngCollector, eventCounts.collectionCountYoung, beanCounts.collectionCountYoung);
321 verifyCollectionCount(oldCollector, eventCounts.collectionCountOld, beanCounts.collectionCountOld);
322 }
323
324 private void verifyCollectionCount(String collector, long eventCounts, long beanCounts) {
325 boolean ignoreFailure =
326 GCHelper.gcConcurrentMarkSweep.equals(collector) || // ConcurrentMarkSweep mixes old and new collections. Not same values as in MXBean.
327 GCHelper.gcG1Old.equals(oldCollector); // MXBean does not report any old collections, so we have nothing to compare with.
328 try {
329 Asserts.assertEquals(eventCounts, beanCounts, "Wrong number of collections for collector " + collector);
330 } catch (Throwable e) {
331 if (ignoreFailure) {
332 System.err.println(String .format("Collector(%s) ignores error: %s", collector, e.getMessage()));
333 } else {
334 throw e;
335 }
336 }
337 }
338
339 /**
340 * Verifies that all events belonging to a single GC are ok.
341 * A GcBatch contains all flight recorder events that belong to a single GC.
342 *
343 * That all gcIds in a batch are the same are verified when the GcBatches are created.
344 *
345 * @param batches flight recorder events grouped into batches belonging to the same GC.
346 */
347 private void verifySingleGcBatch(List<GCHelper.GcBatch> batches) {
348 for (GCHelper.GcBatch batch : batches) {
349 //System.out.println("batch:\r\n" + batch.getLog());
350 try {
351 FLREvent endEvent = batch.getEndEvent();
352
353 Asserts.assertNotNull(endEvent, "No end event in batch.");
354 Asserts.assertNotNull(batch.getName(), "No method name in end event.");
355 Asserts.assertLessOrEqualThan(
356 (Long)endEvent.getValue("longestPause"), (Long)endEvent.getValue("sumOfPauses"),
357 "longest pause should be <= sum pause");
358
359 long startTime = endEvent.getStartTime();
360 long endTime = endEvent.getTimestamp();
361 for (FLREvent event : batch.getEvents()) {
362 Asserts.assertGreaterOrEqualThan(event.getTimestamp(), startTime, "Timestamp in event before start event");
363 Asserts.assertLessOrEqualThan(event.getTimestamp(), endTime, "Timestamp in event after end event");
364 }
365
366 // Verify that all required events has been received.
367 String[] requiredEvents = GCHelper.requiredEvents.get(batch.getName());
368 Asserts.assertNotNull(requiredEvents, "No required events specified for " + batch.getName());
369 for (String requiredEvent : requiredEvents) {
370 boolean b = batch.containsEvent(requiredEvent);
371 Asserts.assertTrue(b, String.format("%s does not contain event %s", batch, requiredEvent));
372 }
373
374 // Verify that we have exactly one heap_summary "Before GC" and one "After GC".
375 int countBeforeGc = 0;
376 int countAfterGc = 0;
377 for (FLREvent event : batch.getEvents()) {
378 if (GCHelper.event_heap_summary.equals(event.getPath())) {
379 String when = (String)((FLRStruct)event.getResolvedValue("when")).getValue("when");
380 if ("Before GC".equals(when)) {
381 countBeforeGc++;
382 } else if ("After GC".equals(when)) {
383 countAfterGc++;
384 } else {
385 Asserts.assertTrue(false, "Unknown value for heap_summary.when: '" + when + "'");
386 }
387 }
388 }
389 if (!GCHelper.gcConcurrentMarkSweep.equals(batch.getName())) {
390 // We do not get heap_summary events for ConcurrentMarkSweep
391 Asserts.assertEquals(1, countBeforeGc, "Unexpected number of heap_summary.before_gc");
392 Asserts.assertEquals(1, countAfterGc, "Unexpected number of heap_summary.after_gc");
393 }
394 } catch (Throwable e) {
395 throw e;
396 }
397 }
398 }
399
400 /**
401 * Verify that all gcId are unique.
402 */
403 private void verifyUniqueIds(List<GCHelper.GcBatch> batches, Set<Integer> gcIds) {
404 for (GCHelper.GcBatch batch : batches) {
405 Integer gcId = new Integer(batch.getGcId());
406 Asserts.assertFalse(gcIds.contains(gcId), "Duplicate gcId: " + gcId);
407 gcIds.add(gcId);
408 }
409 }
410
411 /**
412 * Verify phase events.
413 */
414 private void verifyPhaseEvents(List<GCHelper.GcBatch> batches) {
415 for (GCHelper.GcBatch batch : batches) {
416 for(FLREvent event : batch.getEvents()) {
417 // Only check events that start with "vm/gc/phases/"
418 if (event.getPath().startsWith(GCHelper.event_phases_group)) {
419 long batchStartTime = batch.getEndEvent().getStartTime();
420 Asserts.assertGreaterOrEqualThan(event.getStartTime(), batchStartTime, "Phase startTime >= batch startTime");
421 long minDuration = 0;
422 long duration = event.getTimestamp() - event.getStartTime();
423 Asserts.assertGreaterOrEqualThan(duration, minDuration, "Phase event duration >= " + minDuration);
424 }
425 }
426 }
427 }
428
429 /**
430 * Verifies that the collector name in initial configuration matches the name in garbage configuration event.
431 * If the names are not equal, then we check if this is an expected collector override.
432 * For example, if old collector in initial config is "G1Old" we allow both event "G1Old" and "SerialOld".
433 *
434 * @param batches All event batches.
435 * @param configEvent Initial configuration event.
436 */
437 private void verifyCollectorNames(List<GCHelper.GcBatch> batches) {
438 for (GCHelper.GcBatch batch : batches) {
439 String name = batch.getName();
440 Asserts.assertNotNull(name, "garbage_collection.name was null");
441 boolean isYoung = batch.isYoungCollection();
442 String expectedName = isYoung ? youngCollector : oldCollector;
443 if (!expectedName.equals(name)) {
444 // Collector names not equal. Check if the collector has been overridden by an expected collector.
445 String overrideKey = expectedName + "." + name;
446 boolean isOverride = GCHelper.collectorOverrides.contains(overrideKey);
447 Asserts.assertTrue(isOverride, String.format("Unexpected event name(%s) for collectors(%s, %s)", name, youngCollector, oldCollector));
448 }
449 }
450 }
451
452 /**
453 * Verifies field "cause" in garbage_collection event.
454 * Only check that at cause is not null and that at least 1 cause is "System.gc()"
455 * We might want to check more cause reasons later.
456 *
457 * @param batches All event batches.
458 */
459 private void verifyCollectionCause(List<GCHelper.GcBatch> batches) {
460 int systemGcCount = 0;
461 for (GCHelper.GcBatch batch : batches) {
462 FLREvent endEvent = batch.getEndEvent();
463 String cause = (String)((FLRStruct)endEvent.getResolvedValue("cause")).getValue("cause");
464 Asserts.assertNotNull(cause, "garbage_collection.cause was null");
465 String collectorName = batch.getName();
466 Asserts.assertNotNull(collectorName, "garbage_collection.name was null");
467 if ("System.gc()".equals(cause)) {
468 systemGcCount++;
469 }
470 }
471 Asserts.assertGreaterThan(systemGcCount, 0,
472 String.format("Expected at least 1 cause of System.gc(), collectors(%s, %s)", youngCollector, oldCollector));
473 }
474
475 /**
476 * Log all flight recorder events and to which batches the events belong.
477 * Only log to error file. It is too much to log to System.err.
478 *
479 * @param events All flight recorder events.
480 * @param batches The events grouped into batches belonging to a single GC.
481 */
482 private void log(List<FLREvent> events, List<GCHelper.GcBatch> batches, GCHelper.CollectionSummary eventCounts, GCHelper.CollectionSummary beanCounts) {
483 GCHelper.log("EventCounts:");
484 if (eventCounts != null) {
485 GCHelper.log(eventCounts.toString());
486 }
487 GCHelper.log("BeanCounts:");
488 if (beanCounts != null) {
489 GCHelper.log(beanCounts.toString());
490 }
491 }
492
493 /**
494 * Thread that does a number of System.gc().
495 */
496 public static class SystemGcRunner implements Runnable {
497 private final int totalCollections;
498
499 public SystemGcRunner(int totalCollections) {
500 this.totalCollections = totalCollections;
501 }
502
503 public static SystemGcRunner create(int totalCollections) {
504 return new SystemGcRunner(totalCollections);
505 }
506
507 public void run() {
508 for (int i = 0; i < totalCollections; i++) {
509 GCEventAll.doSystemGc();
510 }
511 }
512 }
513
514 /**
515 * Thread that creates garbage until a certain number of GCs has been run.
516 */
517 public static class GarbageRunner implements Runnable {
518 private final int totalCollections;
519 public byte[] dummyBuffer = null;
520
521 public GarbageRunner(int totalCollections) {
522 this.totalCollections = totalCollections;
523 }
524
525 public static GarbageRunner create(int totalCollections) {
526 return new GarbageRunner(totalCollections);
527 }
528
529 public void run() {
530 long currCollections = GCHelper.CollectionSummary.createFromMxBeans().sum();
531 long endCollections = totalCollections + currCollections;
532 Random r = new Random(0);
533 while (true) {
534 for (int i = 0; i < 1000; i++) {
535 dummyBuffer = new byte[r.nextInt(10000)];
536 }
537 if (GCHelper.CollectionSummary.createFromMxBeans().sum() >= endCollections) {
538 break;
539 }
540 }
541 }
542 }
543
544 /**
545 * Thread that runs System.gc() and then wait for a number of GCs or a maximum time.
546 */
547 public static class SystemGcWaitRunner implements Runnable {
548 private final int totalCollections;
549 private final int minWaitCollections;
550 private final long maxWaitMillis;
551
552 public SystemGcWaitRunner(int totalCollections, int minWaitCollections, long maxWaitMillis) {
553 this.totalCollections = totalCollections;
554 this.minWaitCollections = minWaitCollections;
555 this.maxWaitMillis = maxWaitMillis;
556 }
557
558 public static SystemGcWaitRunner create(int deltaCollections, int minWaitCollections, long maxWaitMillis) {
559 return new SystemGcWaitRunner(deltaCollections, minWaitCollections, maxWaitMillis);
560 }
561
562 public void run() {
563 long currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();
564 long endCount = totalCollections + currCount;
565 long nextSystemGcCount = currCount + minWaitCollections;
566 long now = System.currentTimeMillis();
567 long nextSystemGcMillis = now + maxWaitMillis;
568
569 while (true) {
570 if (currCount >= nextSystemGcCount || System.currentTimeMillis() > nextSystemGcMillis) {
571 GCEventAll.doSystemGc();
572 currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();
573 nextSystemGcCount = currCount + minWaitCollections;
574 } else {
575 try {
576 Thread.sleep(20);
577 } catch (InterruptedException e) {
578 e.printStackTrace();
579 break;
580 }
581 }
582 currCount = GCHelper.CollectionSummary.createFromMxBeans().sum();
583 if (currCount >= endCount) {
584 break;
585 }
586 }
587 }
588 }
589
590 }