8027962: Per-phase timing measurements for strong roots processing

Reviewed-by: tschatzl, ecaspole

src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp

@@ -249,7 +249,24 @@ G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
 
   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2);
   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2);
-  _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFiner, 2);
+
+  // Root scanning phases
+  _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[CodeCacheRoots] = new WorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3);
+  _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3);
+
   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);
   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);
   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);
@@ -282,8 +299,6 @@ void G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress
     _gc_par_phases[i]->reset();
   }
 
-  _gc_par_phases[SATBFiltering]->set_enabled(mark_in_progress);
-
   _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
   _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
 }

src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp

@@ -41,6 +41,20 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   enum GCParPhases {
     GCWorkerStart,
     ExtRootScan,
+    ThreadRoots,
+    StringTableRoots,
+    UniverseRoots,
+    JNIRoots,
+    ObjectSynchronizerRoots,
+    FlatProfilerRoots,
+    ManagementRoots,
+    SystemDictionaryRoots,
+    CLDGRoots,
+    JVMTIRoots,
+    CodeCacheRoots,
+    CMRefRoots,
+    WaitForStrongCLD,
+    WeakCLDRoots,
     SATBFiltering,
     UpdateRS,
     ScanRS,

src/share/vm/gc_implementation/g1/g1RootProcessor.cpp

@@ -128,6 +128,7 @@ void G1RootProcessor::evacuate_roots(OopClosure* scan_non_heap_roots,
                                      uint worker_i) {
   // First scan the shared roots.
   double ext_roots_start = os::elapsedTime();
+  G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times();
 
   BufferingOopClosure buf_scan_non_heap_roots(scan_non_heap_roots);
   BufferingOopClosure buf_scan_non_heap_weak_roots(scan_non_heap_weak_roots);
@@ -142,7 +143,9 @@ void G1RootProcessor::evacuate_roots(OopClosure* scan_non_heap_roots,
                      trace_metadata ? scan_strong_clds : NULL,
                      scan_strong_clds,
                      trace_metadata ? NULL : scan_weak_clds,
-                     &root_code_blobs);
+                     &root_code_blobs,
+                     phase_times,
+                     worker_i);
 
   // This is the point where this worker thread will not find more strong CLDs/nmethods.
   // Report this so G1 can synchronize the strong and weak CLDs/nmethods processing.
@@ -150,24 +153,34 @@ void G1RootProcessor::evacuate_roots(OopClosure* scan_non_heap_roots,
     worker_has_discovered_all_strong_classes();
   }
 
-  process_vm_roots(strong_roots, weak_roots);
+  process_vm_roots(strong_roots, weak_roots, phase_times, worker_i);
 
-  // Now the CM ref_processor roots.
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_refProcessor_oops_do)) {
-    // We need to treat the discovered reference lists of the
-    // concurrent mark ref processor as roots and keep entries
-    // (which are added by the marking threads) on them live
-    // until they can be processed at the end of marking.
-    _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots);
+  {
+    // Now the CM ref_processor roots.
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CMRefRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_refProcessor_oops_do)) {
+      // We need to treat the discovered reference lists of the
+      // concurrent mark ref processor as roots and keep entries
+      // (which are added by the marking threads) on them live
+      // until they can be processed at the end of marking.
+      _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots);
+    }
   }
 
   if (trace_metadata) {
-    // Barrier to make sure all workers passed
-    // the strong CLD and strong nmethods phases.
-    wait_until_all_strong_classes_discovered();
+    {
+      G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::WaitForStrongCLD, worker_i);
+      // Barrier to make sure all workers passed
+      // the strong CLD and strong nmethods phases.
+      wait_until_all_strong_classes_discovered();
+    }
 
     // Now take the complement of the strong CLDs.
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::WeakCLDRoots, worker_i);
     ClassLoaderDataGraph::roots_cld_do(NULL, scan_weak_clds);
+  } else {
+    phase_times->record_time_secs(G1GCPhaseTimes::WaitForStrongCLD, worker_i, 0.0);
+    phase_times->record_time_secs(G1GCPhaseTimes::WeakCLDRoots, worker_i, 0.0);
   }
 
   // Finish up any enqueued closure apps (attributed as object copy time).
@@ -177,7 +190,6 @@ void G1RootProcessor::evacuate_roots(OopClosure* scan_non_heap_roots,
   double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds()
       + buf_scan_non_heap_weak_roots.closure_app_seconds();
 
-  G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times();
   phase_times->record_time_secs(G1GCPhaseTimes::ObjCopy, worker_i, obj_copy_time_sec);
 
   double ext_root_time_sec = os::elapsedTime() - ext_roots_start - obj_copy_time_sec;
@@ -201,8 +213,8 @@ void G1RootProcessor::process_strong_roots(OopClosure* oops,
                                            CLDClosure* clds,
                                            CodeBlobClosure* blobs) {
 
-  process_java_roots(oops, clds, clds, NULL, blobs);
-  process_vm_roots(oops, NULL);
+  process_java_roots(oops, clds, clds, NULL, blobs, NULL, 0);
+  process_vm_roots(oops, NULL, NULL, 0);
 
   _process_strong_tasks->all_tasks_completed();
 }
@@ -211,8 +223,8 @@ void G1RootProcessor::process_all_roots(OopClosure* oops,
                                         CLDClosure* clds,
                                         CodeBlobClosure* blobs) {
 
-  process_java_roots(oops, NULL, clds, clds, NULL);
-  process_vm_roots(oops, oops);
+  process_java_roots(oops, NULL, clds, clds, NULL, NULL, 0);
+  process_vm_roots(oops, oops, NULL, 0);
 
   if (!_process_strong_tasks->is_task_claimed(G1RP_PS_CodeCache_oops_do)) {
     CodeCache::blobs_do(blobs);
@@ -225,60 +237,95 @@ void G1RootProcessor::process_java_roots(OopClosure* strong_roots,
                                          CLDClosure* thread_stack_clds,
                                          CLDClosure* strong_clds,
                                          CLDClosure* weak_clds,
-                                         CodeBlobClosure* strong_code) {
+                                         CodeBlobClosure* strong_code,
+                                         G1GCPhaseTimes* phase_times,
+                                         uint worker_i) {
   assert(thread_stack_clds == NULL || weak_clds == NULL, "There is overlap between those, only one may be set");
   // Iterating over the CLDG and the Threads are done early to allow us to
   // first process the strong CLDs and nmethods and then, after a barrier,
   // let the thread process the weak CLDs and nmethods.
-
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_ClassLoaderDataGraph_oops_do)) {
-    ClassLoaderDataGraph::roots_cld_do(strong_clds, weak_clds);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CLDGRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_ClassLoaderDataGraph_oops_do)) {
+      ClassLoaderDataGraph::roots_cld_do(strong_clds, weak_clds);
+    }
   }
 
-  Threads::possibly_parallel_oops_do(strong_roots, thread_stack_clds, strong_code);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ThreadRoots, worker_i);
+    Threads::possibly_parallel_oops_do(strong_roots, thread_stack_clds, strong_code);
+  }
 }
 
 void G1RootProcessor::process_vm_roots(OopClosure* strong_roots,
-                                       OopClosure* weak_roots) {
-
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Universe_oops_do)) {
-    Universe::oops_do(strong_roots);
+                                       OopClosure* weak_roots,
+                                       G1GCPhaseTimes* phase_times,
+                                       uint worker_i) {
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::UniverseRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Universe_oops_do)) {
+      Universe::oops_do(strong_roots);
+    }
   }
 
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_JNIHandles_oops_do)) {
-    JNIHandles::oops_do(strong_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::JNIRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_JNIHandles_oops_do)) {
+      JNIHandles::oops_do(strong_roots);
+    }
   }
 
-  if (!_process_strong_tasks-> is_task_claimed(G1RP_PS_ObjectSynchronizer_oops_do)) {
-    ObjectSynchronizer::oops_do(strong_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ObjectSynchronizerRoots, worker_i);
+    if (!_process_strong_tasks-> is_task_claimed(G1RP_PS_ObjectSynchronizer_oops_do)) {
+      ObjectSynchronizer::oops_do(strong_roots);
+    }
   }
 
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_FlatProfiler_oops_do)) {
-    FlatProfiler::oops_do(strong_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::FlatProfilerRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_FlatProfiler_oops_do)) {
+      FlatProfiler::oops_do(strong_roots);
+    }
   }
 
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Management_oops_do)) {
-    Management::oops_do(strong_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ManagementRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Management_oops_do)) {
+      Management::oops_do(strong_roots);
+    }
   }
 
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_jvmti_oops_do)) {
-    JvmtiExport::oops_do(strong_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::JVMTIRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_jvmti_oops_do)) {
+      JvmtiExport::oops_do(strong_roots);
+    }
   }
 
-  if (!_process_strong_tasks->is_task_claimed(G1RP_PS_SystemDictionary_oops_do)) {
-    SystemDictionary::roots_oops_do(strong_roots, weak_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::SystemDictionaryRoots, worker_i);
+    if (!_process_strong_tasks->is_task_claimed(G1RP_PS_SystemDictionary_oops_do)) {
+      SystemDictionary::roots_oops_do(strong_roots, weak_roots);
+    }
   }
 
-  // All threads execute the following. A specific chunk of buckets
-  // from the StringTable are the individual tasks.
-  if (weak_roots != NULL) {
-    StringTable::possibly_parallel_oops_do(weak_roots);
+  {
+    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::StringTableRoots, worker_i);
+    // All threads execute the following. A specific chunk of buckets
+    // from the StringTable are the individual tasks.
+    if (weak_roots != NULL) {
+      StringTable::possibly_parallel_oops_do(weak_roots);
+    }
   }
 }
 
 void G1RootProcessor::scan_remembered_sets(G1ParPushHeapRSClosure* scan_rs,
                                            OopClosure* scan_non_heap_weak_roots,
                                            uint worker_i) {
+  G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times();
+  G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CodeCacheRoots, worker_i);
+
   // Now scan the complement of the collection set.
   G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots);
 

src/share/vm/gc_implementation/g1/g1RootProcessor.hpp

@@ -32,6 +32,7 @@
 class CLDClosure;
 class CodeBlobClosure;
 class G1CollectedHeap;
+class G1GCPhaseTimes;
 class G1ParPushHeapRSClosure;
 class Monitor;
 class OopClosure;
@@ -74,10 +75,14 @@ class G1RootProcessor : public StackObj {
                           CLDClosure* thread_stack_clds,
                           CLDClosure* scan_strong_clds,
                           CLDClosure* scan_weak_clds,
-                          CodeBlobClosure* scan_strong_code);
+                          CodeBlobClosure* scan_strong_code,
+                          G1GCPhaseTimes* phase_times,
+                          uint worker_i);
 
   void process_vm_roots(OopClosure* scan_non_heap_roots,
-                        OopClosure* scan_non_heap_weak_roots);
+                        OopClosure* scan_non_heap_weak_roots,
+                        G1GCPhaseTimes* phase_times,
+                        uint worker_i);
 
 public:
   G1RootProcessor(G1CollectedHeap* g1h);

test/gc/g1/TestGCLogMessages.java

 /*
- * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2014, 2015 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
@@ -23,7 +23,7 @@
 
 /*
  * @test TestGCLogMessages
- * @bug 8035406 8027295 8035398 8019342 8027959
+ * @bug 8035406 8027295 8035398 8019342 8027959 8027962
  * @summary Ensure that the PrintGCDetails output for a minor GC with G1
  * includes the expected necessary messages.
  * @key gc
@@ -34,128 +34,158 @@ import com.oracle.java.testlibrary.ProcessTools;
 import com.oracle.java.testlibrary.OutputAnalyzer;
 
 public class TestGCLogMessages {
-  public static void main(String[] args) throws Exception {
-    testNormalLogs();
-    testWithToSpaceExhaustionLogs();
-  }
-
-  private static void testNormalLogs() throws Exception {
-
-    ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
-                                                              "-Xmx10M",
-                                                              GCTest.class.getName());
-
-    OutputAnalyzer output = new OutputAnalyzer(pb.start());
-
-    output.shouldNotContain("[Redirty Cards");
-    output.shouldNotContain("[Parallel Redirty");
-    output.shouldNotContain("[Redirtied Cards");
-    output.shouldNotContain("[Code Root Purge");
-    output.shouldNotContain("[String Dedup Fixup");
-    output.shouldNotContain("[Young Free CSet");
-    output.shouldNotContain("[Non-Young Free CSet");
-    output.shouldNotContain("[Humongous Reclaim");
-    output.shouldHaveExitValue(0);
-
-    pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
-                                               "-XX:+UseStringDeduplication",
-                                               "-Xmx10M",
-                                               "-XX:+PrintGCDetails",
-                                               GCTest.class.getName());
-
-    output = new OutputAnalyzer(pb.start());
-
-    output.shouldContain("[Redirty Cards");
-    output.shouldNotContain("[Parallel Redirty");
-    output.shouldNotContain("[Redirtied Cards");
-    output.shouldContain("[Code Root Purge");
-    output.shouldContain("[String Dedup Fixup");
-    output.shouldNotContain("[Young Free CSet");
-    output.shouldNotContain("[Non-Young Free CSet");
-    output.shouldContain("[Humongous Reclaim");
-    output.shouldNotContain("[Humongous Total");
-    output.shouldNotContain("[Humongous Candidate");
-    output.shouldNotContain("[Humongous Reclaimed");
-    output.shouldHaveExitValue(0);
-
-    pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
-                                               "-XX:+UseStringDeduplication",
-                                               "-Xmx10M",
-                                               "-XX:+PrintGCDetails",
-                                               "-XX:+UnlockExperimentalVMOptions",
-                                               "-XX:G1LogLevel=finest",
-                                               GCTest.class.getName());
-
-    output = new OutputAnalyzer(pb.start());
-
-    output.shouldContain("[Redirty Cards");
-    output.shouldContain("[Parallel Redirty");
-    output.shouldContain("[Redirtied Cards");
-    output.shouldContain("[Code Root Purge");
-    output.shouldContain("[String Dedup Fixup");
-    output.shouldContain("[Young Free CSet");
-    output.shouldContain("[Non-Young Free CSet");
-    output.shouldContain("[Humongous Reclaim");
-    output.shouldContain("[Humongous Total");
-    output.shouldContain("[Humongous Candidate");
-    output.shouldContain("[Humongous Reclaimed");
-    output.shouldHaveExitValue(0);
-  }
-
-  private static void testWithToSpaceExhaustionLogs() throws Exception {
-    ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
-                                               "-Xmx10M",
-                                               "-Xmn5M",
-                                               "-XX:+PrintGCDetails",
-                                               GCTestWithToSpaceExhaustion.class.getName());
-
-    OutputAnalyzer output = new OutputAnalyzer(pb.start());
-    output.shouldContain("[Evacuation Failure");
-    output.shouldNotContain("[Recalculate Used");
-    output.shouldNotContain("[Remove Self Forwards");
-    output.shouldNotContain("[Restore RemSet");
-    output.shouldHaveExitValue(0);
-
-    pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
-                                               "-Xmx10M",
-                                               "-Xmn5M",
-                                               "-XX:+PrintGCDetails",
-                                               "-XX:+UnlockExperimentalVMOptions",
-                                               "-XX:G1LogLevel=finest",
-                                               GCTestWithToSpaceExhaustion.class.getName());
-
-    output = new OutputAnalyzer(pb.start());
-    output.shouldContain("[Evacuation Failure");
-    output.shouldContain("[Recalculate Used");
-    output.shouldContain("[Remove Self Forwards");
-    output.shouldContain("[Restore RemSet");
-    output.shouldHaveExitValue(0);
-  }
-
-  static class GCTest {
-    private static byte[] garbage;
-    public static void main(String [] args) {
-      System.out.println("Creating garbage");
-      // create 128MB of garbage. This should result in at least one GC
-      for (int i = 0; i < 1024; i++) {
-        garbage = new byte[128 * 1024];
-      }
-      System.out.println("Done");
+
+    private enum Level {
+        OFF, FINER, FINEST;
+        public boolean lessOrEqualTo(Level other) {
+            return this.compareTo(other) < 0;
+        }
     }
-  }
-
-  static class GCTestWithToSpaceExhaustion {
-    private static byte[] garbage;
-    private static byte[] largeObject;
-    public static void main(String [] args) {
-      largeObject = new byte[5*1024*1024];
-      System.out.println("Creating garbage");
-      // create 128MB of garbage. This should result in at least one GC,
-      // some of them with to-space exhaustion.
-      for (int i = 0; i < 1024; i++) {
-        garbage = new byte[128 * 1024];
-      }
-      System.out.println("Done");
+
+    private class LogMessageWithLevel {
+        String message;
+        Level level;
+
+        public LogMessageWithLevel(String message, Level level) {
+            this.message = message;
+            this.level = level;
+        }
+    };
+
+    private LogMessageWithLevel allLogMessages[] = new LogMessageWithLevel[] {
+        // Ext Root Scan
+        new LogMessageWithLevel("Thread Roots (ms)", Level.FINEST),
+        new LogMessageWithLevel("StringTable Roots (ms)", Level.FINEST),
+        new LogMessageWithLevel("Universe Roots (ms)", Level.FINEST),
+        new LogMessageWithLevel("JNI Handles Roots (ms)", Level.FINEST),
+        new LogMessageWithLevel("ObjectSynchronizer Roots (ms)", Level.FINEST),
+        new LogMessageWithLevel("FlatProfiler Roots", Level.FINEST),
+        new LogMessageWithLevel("Management Roots", Level.FINEST),
+        new LogMessageWithLevel("SystemDictionary Roots", Level.FINEST),
+        new LogMessageWithLevel("CLDG Roots", Level.FINEST),
+        new LogMessageWithLevel("JVMTI Roots", Level.FINEST),
+        new LogMessageWithLevel("CodeCache Roots", Level.FINEST),
+        new LogMessageWithLevel("SATB Filtering", Level.FINEST),
+        new LogMessageWithLevel("CM RefProcessor Roots", Level.FINEST),
+        new LogMessageWithLevel("Wait For Strong CLD", Level.FINEST),
+        new LogMessageWithLevel("Weak CLD Roots", Level.FINEST),
+        // Redirty Cards
+        new LogMessageWithLevel("Redirty Cards", Level.FINER),
+        new LogMessageWithLevel("Parallel Redirty", Level.FINEST),
+        new LogMessageWithLevel("Redirtied Cards", Level.FINEST),
+        // Misc Top-level
+        new LogMessageWithLevel("Code Root Purge", Level.FINER),
+        new LogMessageWithLevel("String Dedup Fixup", Level.FINER),
+        // Free CSet
+        new LogMessageWithLevel("Young Free CSet", Level.FINEST),
+        new LogMessageWithLevel("Non-Young Free CSet", Level.FINEST),
+        // Humongous Eager Reclaim
+        new LogMessageWithLevel("Humongous Reclaim", Level.FINER),
+    };
+
+    void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception {
+        for (LogMessageWithLevel l : messages) {
+            if (level.lessOrEqualTo(l.level)) {
+                output.shouldNotContain(l.message);
+            } else {
+                output.shouldContain(l.message);
+            }
+        }
+    }
+
+    public static void main(String[] args) throws Exception {
+        new TestGCLogMessages().testNormalLogs();
+        new TestGCLogMessages().testWithToSpaceExhaustionLogs();
+    }
+
+    private void testNormalLogs() throws Exception {
+
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                                  "-Xmx10M",
+                                                                  GCTest.class.getName());
+
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        checkMessagesAtLevel(output, allLogMessages, Level.OFF);
+        output.shouldHaveExitValue(0);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                   "-XX:+UseStringDeduplication",
+                                                   "-Xmx10M",
+                                                   "-XX:+PrintGCDetails",
+                                                   GCTest.class.getName());
+
+        output = new OutputAnalyzer(pb.start());
+        checkMessagesAtLevel(output, allLogMessages, Level.FINER);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                   "-XX:+UseStringDeduplication",
+                                                   "-Xmx10M",
+                                                   "-XX:+PrintGCDetails",
+                                                   "-XX:+UnlockExperimentalVMOptions",
+                                                   "-XX:G1LogLevel=finest",
+                                                   GCTest.class.getName());
+
+        output = new OutputAnalyzer(pb.start());
+        checkMessagesAtLevel(output, allLogMessages, Level.FINEST);
+        output.shouldHaveExitValue(0);
+    }
+
+    LogMessageWithLevel exhFailureMessages[] = new LogMessageWithLevel[] {
+        new LogMessageWithLevel("Evacuation Failure", Level.FINER),
+        new LogMessageWithLevel("Recalculate Used", Level.FINEST),
+        new LogMessageWithLevel("Remove Self Forwards", Level.FINEST),
+        new LogMessageWithLevel("Restore RemSet", Level.FINEST),
+    };
+
+    private void testWithToSpaceExhaustionLogs() throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                                  "-Xmx32M",
+                                                                  "-Xmn16M",
+                                                                  "-XX:+PrintGCDetails",
+                                                                  GCTestWithToSpaceExhaustion.class.getName());
+
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        checkMessagesAtLevel(output, exhFailureMessages, Level.FINER);
+        output.shouldHaveExitValue(0);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                   "-Xmx32M",
+                                                   "-Xmn16M",
+                                                   "-XX:+PrintGCDetails",
+                                                   "-XX:+UnlockExperimentalVMOptions",
+                                                   "-XX:G1LogLevel=finest",
+                                                   GCTestWithToSpaceExhaustion.class.getName());
+
+        output = new OutputAnalyzer(pb.start());
+        checkMessagesAtLevel(output, exhFailureMessages, Level.FINEST);
+        output.shouldHaveExitValue(0);
+    }
+
+    static class GCTest {
+        private static byte[] garbage;
+        public static void main(String [] args) {
+            System.out.println("Creating garbage");
+            // create 128MB of garbage. This should result in at least one GC
+            for (int i = 0; i < 1024; i++) {
+                garbage = new byte[128 * 1024];
+            }
+            System.out.println("Done");
+        }
+    }
+
+    static class GCTestWithToSpaceExhaustion {
+        private static byte[] garbage;
+        private static byte[] largeObject;
+        public static void main(String [] args) {
+            largeObject = new byte[16*1024*1024];
+            System.out.println("Creating garbage");
+            // create 128MB of garbage. This should result in at least one GC,
+            // some of them with to-space exhaustion.
+            for (int i = 0; i < 1024; i++) {
+                garbage = new byte[128 * 1024];
+            }
+            System.out.println("Done");
+        }
     }
-  }
 }
+