8272651: G1 heap region info print order changed by JDK-8269914

Reviewed-by: tschatzl, iwalulya, ayang

src/hotspot/share/gc/g1/g1CollectedHeap.cpp

@@ -1113,8 +1113,9 @@ bool G1CollectedHeap::do_full_collection(bool explicit_gc,
   const bool do_clear_all_soft_refs = clear_all_soft_refs ||
       soft_ref_policy()->should_clear_all_soft_refs();
 
-  G1FullCollector collector(this, explicit_gc, do_clear_all_soft_refs, do_maximum_compaction);
+  G1FullGCMark gc_mark;
   GCTraceTime(Info, gc) tm("Pause Full", NULL, gc_cause(), true);
+  G1FullCollector collector(this, explicit_gc, do_clear_all_soft_refs, do_maximum_compaction);
 
   collector.prepare_collection();
   collector.collect();
@@ -3048,10 +3049,6 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
   bool should_start_concurrent_mark_operation = collector_state()->in_concurrent_start_gc();
   bool concurrent_operation_is_full_mark = false;
 
-  // Verification may use the gang workers, so they must be set up before.
-  // Individual parallel phases may override this.
-  set_young_collection_default_active_worker_threads();
-
   {
     // Do timing/tracing/statistics/pre- and post-logging/verification work not
     // directly related to the collection. They should not be accounted for in
@@ -3061,16 +3058,21 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
     // determining collector state.
     G1YoungGCTraceTime tm(gc_cause());
 
-    // Young GC internal pause timing
-    G1YoungGCNotifyPauseMark npm;
     // JFR
     G1YoungGCJFRTracerMark jtm(_gc_timer_stw, _gc_tracer_stw, gc_cause());
     // JStat/MXBeans
     G1MonitoringScope ms(monitoring_support(),
                          false /* full_gc */,
                          collector_state()->in_mixed_phase() /* all_memory_pools_affected */);
-
+    // Create the heap printer before internal pause timing to have
+    // heap information printed as last part of detailed GC log.
     G1HeapPrinterMark hpm(this);
+    // Young GC internal pause timing
+    G1YoungGCNotifyPauseMark npm;
+
+    // Verification may use the gang workers, so they must be set up before.
+    // Individual parallel phases may override this.
+    set_young_collection_default_active_worker_threads();
 
     // Wait for root region scan here to make sure that it is done before any
     // use of the STW work gang to maximize cpu use (i.e. all cores are available

src/hotspot/share/gc/g1/g1FullCollector.hpp

@@ -31,6 +31,8 @@
 #include "gc/g1/g1FullGCOopClosures.hpp"
 #include "gc/g1/g1FullGCScope.hpp"
 #include "gc/g1/g1RegionMarkStatsCache.hpp"
+#include "gc/shared/gcId.hpp"
+#include "gc/shared/gcTraceTime.hpp"
 #include "gc/shared/preservedMarks.hpp"
 #include "gc/shared/referenceProcessor.hpp"
 #include "gc/shared/taskqueue.hpp"
@@ -55,6 +57,16 @@ class G1FullGCSubjectToDiscoveryClosure: public BoolObjectClosure {
   }
 };
 
+// Full GC Mark that holds GC id and CPU time trace. Needs to be separate
+// from the G1FullCollector and G1FullGCScope to allow the Full GC logging
+// to have the same structure as the Young GC logging.
+class G1FullGCMark : StackObj {
+  GCIdMark       _gc_id;
+  GCTraceCPUTime _cpu_time;
+public:
+  G1FullGCMark() : _gc_id(), _cpu_time() { }
+};
+
 // The G1FullCollector holds data associated with the current Full GC.
 class G1FullCollector : StackObj {
   G1CollectedHeap*          _heap;

src/hotspot/share/gc/g1/g1FullGCScope.cpp

@@ -42,12 +42,10 @@ G1FullGCScope::G1FullGCScope(G1MonitoringSupport* monitoring_support,
     _rm(),
     _explicit_gc(explicit_gc),
     _g1h(G1CollectedHeap::heap()),
-    _gc_id(),
     _svc_marker(SvcGCMarker::FULL),
     _timer(),
     _tracer(),
     _active(),
-    _cpu_time(),
     _tracer_mark(&_timer, &_tracer),
     _soft_refs(clear_soft, _g1h->soft_ref_policy()),
     _monitoring_scope(monitoring_support, true /* full_gc */, true /* all_memory_pools_affected */),

src/hotspot/share/gc/g1/g1FullGCScope.hpp

@@ -28,8 +28,6 @@
 #include "gc/g1/g1CollectedHeap.hpp"
 #include "gc/g1/g1HeapTransition.hpp"
 #include "gc/g1/g1Trace.hpp"
-#include "gc/shared/gcId.hpp"
-#include "gc/shared/gcTraceTime.hpp"
 #include "gc/shared/gcTimer.hpp"
 #include "gc/shared/gcVMOperations.hpp"
 #include "gc/shared/isGCActiveMark.hpp"
@@ -51,12 +49,10 @@ class G1FullGCScope : public StackObj {
   ResourceMark            _rm;
   bool                    _explicit_gc;
   G1CollectedHeap*        _g1h;
-  GCIdMark                _gc_id;
   SvcGCMarker             _svc_marker;
   STWGCTimer              _timer;
   G1FullGCTracer          _tracer;
   IsGCActiveMark          _active;
-  GCTraceCPUTime          _cpu_time;
   G1FullGCJFRTracerMark   _tracer_mark;
   ClearedAllSoftRefs      _soft_refs;
   G1MonitoringScope       _monitoring_scope;

test/hotspot/jtreg/gc/g1/TestEagerReclaimHumongousRegionsLog.java

@@ -73,12 +73,12 @@ public static void runTest() throws Exception {
 
         // This gives an array of lines containing eager reclaim of humongous regions
         // log messages contents after the ":" in the following order for every GC:
-        //   Humongous Regions: f->g
         //   Region Register: a.ams
         //   Eagerly Reclaim Humonguous Objects b.cms
         //   Humongous Total: Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: c, Workers: 1
         //   Humongous Candidate: Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: d, Workers: 1
         //   Humongous Reclaimed: Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: e, Workers: 1
+        //   Humongous Regions: f->g
 
         String[] lines = Arrays.stream(output.getStdout().split("\\R"))
                          .filter(s -> (s.contains("Humongous") || s.contains("Region Register"))).map(s -> s.substring(s.indexOf(LogSeparator) + LogSeparator.length()))
@@ -87,12 +87,12 @@ public static void runTest() throws Exception {
         Asserts.assertTrue(lines.length % 6 == 0, "There seems to be an unexpected amount of log messages (total: " + lines.length + ") per GC");
 
         for (int i = 0; i < lines.length; i += 6) {
-            int total = Integer.parseInt(getSumValue(lines[i + 3]));
-            int candidate = Integer.parseInt(getSumValue(lines[i + 4]));
-            int reclaimed = Integer.parseInt(getSumValue(lines[i + 5]));
+            int total = Integer.parseInt(getSumValue(lines[i + 2]));
+            int candidate = Integer.parseInt(getSumValue(lines[i + 3]));
+            int reclaimed = Integer.parseInt(getSumValue(lines[i + 4]));
 
-            int before = Integer.parseInt(lines[i].substring(0, 1));
-            int after = Integer.parseInt(lines[i].substring(3, 4));
+            int before = Integer.parseInt(lines[i + 5].substring(0, 1));
+            int after = Integer.parseInt(lines[i + 5].substring(3, 4));
             System.out.println("total " + total + " candidate " + candidate + " reclaimed " + reclaimed + " before " + before + " after " + after);
 
             Asserts.assertEQ(total, candidate, "Not all humonguous objects are candidates");