8027962: Per-phase timing measurements for strong roots processing

Reviewed-by: tschatzl, ecaspole

hotspot/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());
 }

hotspot/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,

hotspot/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,9 +153,11 @@ 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.
+    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
@@ -160,14 +165,22 @@ void G1RootProcessor::evacuate_roots(OopClosure* scan_non_heap_roots,
       // 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) {
+    {
+      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_java_roots(oops, clds, clds, NULL, blobs, NULL, 0);
-  process_vm_roots(oops, NULL);
+  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_java_roots(oops, NULL, clds, clds, NULL, NULL, 0);
-  process_vm_roots(oops, oops);
+  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.
-
+  {
+    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);
     }
+  }
 
+  {
+    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) {
+                                       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);
     }
+  }
 
+  {
+    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);
     }
+  }
 
+  {
+    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);
     }
+  }
 
+  {
+    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);
     }
+  }
 
+  {
+    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);
     }
+  }
 
+  {
+    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);
     }
+  }
 
+  {
+    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);
     }
+  }
 
+  {
+    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);
 

hotspot/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);

hotspot/test/gc/g1/TestGCLogMessages.java

@@ -1,5 +1,5 @@
 /*
- * 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 8048179
+ * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962
  * @summary Ensure that the PrintGCDetails output for a minor GC with G1
  * includes the expected necessary messages.
  * @key gc
@@ -34,28 +34,79 @@ import com.oracle.java.testlibrary.ProcessTools;
 import com.oracle.java.testlibrary.OutputAnalyzer;
 
 public class TestGCLogMessages {
+
+    private enum Level {
+        OFF, FINER, FINEST;
+        public boolean lessOrEqualTo(Level other) {
+            return this.compareTo(other) < 0;
+        }
+    }
+
+    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),
+        new LogMessageWithLevel("Humongous Register", 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 {
-    testNormalLogs();
+        new TestGCLogMessages().testNormalLogs();
-    testWithToSpaceExhaustionLogs();
+        new TestGCLogMessages().testWithToSpaceExhaustionLogs();
     }
 
-  private static void testNormalLogs() throws Exception {
+    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.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 Register");
-    output.shouldNotContain("[Humongous Reclaim");
         output.shouldHaveExitValue(0);
 
         pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
@@ -65,20 +116,7 @@ public class TestGCLogMessages {
                                                    GCTest.class.getName());
 
         output = new OutputAnalyzer(pb.start());
-
+        checkMessagesAtLevel(output, allLogMessages, Level.FINER);
-    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 Register");
-    output.shouldNotContain("[Humongous Total");
-    output.shouldNotContain("[Humongous Candidate");
-    output.shouldContain("[Humongous Reclaim");
-    output.shouldNotContain("[Humongous Reclaimed");
-    output.shouldHaveExitValue(0);
 
         pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
                                                    "-XX:+UseStringDeduplication",
@@ -89,23 +127,18 @@ public class TestGCLogMessages {
                                                    GCTest.class.getName());
 
         output = new OutputAnalyzer(pb.start());
-
+        checkMessagesAtLevel(output, allLogMessages, Level.FINEST);
-    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 Register");
-    output.shouldContain("[Humongous Total");
-    output.shouldContain("[Humongous Candidate");
-    output.shouldContain("[Humongous Reclaim");
-    output.shouldContain("[Humongous Reclaimed");
         output.shouldHaveExitValue(0);
     }
 
-  private static void testWithToSpaceExhaustionLogs() throws Exception {
+    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",
@@ -113,10 +146,7 @@ public class TestGCLogMessages {
                                                                   GCTestWithToSpaceExhaustion.class.getName());
 
         OutputAnalyzer output = new OutputAnalyzer(pb.start());
-    output.shouldContain("[Evacuation Failure");
+        checkMessagesAtLevel(output, exhFailureMessages, Level.FINER);
-    output.shouldNotContain("[Recalculate Used");
-    output.shouldNotContain("[Remove Self Forwards");
-    output.shouldNotContain("[Restore RemSet");
         output.shouldHaveExitValue(0);
 
         pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
@@ -128,10 +158,7 @@ public class TestGCLogMessages {
                                                    GCTestWithToSpaceExhaustion.class.getName());
 
         output = new OutputAnalyzer(pb.start());
-    output.shouldContain("[Evacuation Failure");
+        checkMessagesAtLevel(output, exhFailureMessages, Level.FINEST);
-    output.shouldContain("[Recalculate Used");
-    output.shouldContain("[Remove Self Forwards");
-    output.shouldContain("[Restore RemSet");
         output.shouldHaveExitValue(0);
     }
 
@@ -162,3 +189,4 @@ public class TestGCLogMessages {
         }
     }
 }
+