From f11e099a149adfecc474ba37276ec8672067d090 Mon Sep 17 00:00:00 2001 From: Stefan Johansson Date: Mon, 30 Aug 2021 14:37:03 +0000 Subject: [PATCH] 8272651: G1 heap region info print order changed by JDK-8269914 Reviewed-by: tschatzl, iwalulya, ayang --- src/hotspot/share/gc/g1/g1CollectedHeap.cpp | 18 ++++++++++-------- src/hotspot/share/gc/g1/g1FullCollector.hpp | 12 ++++++++++++ src/hotspot/share/gc/g1/g1FullGCScope.cpp | 2 -- src/hotspot/share/gc/g1/g1FullGCScope.hpp | 4 ---- .../TestEagerReclaimHumongousRegionsLog.java | 12 ++++++------ 5 files changed, 28 insertions(+), 20 deletions(-) diff --git a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp index 5840b6a2662..bf2629560b1 100644 --- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp +++ b/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 diff --git a/src/hotspot/share/gc/g1/g1FullCollector.hpp b/src/hotspot/share/gc/g1/g1FullCollector.hpp index a2fdbfbf5f7..1f9c12abd24 100644 --- a/src/hotspot/share/gc/g1/g1FullCollector.hpp +++ b/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; diff --git a/src/hotspot/share/gc/g1/g1FullGCScope.cpp b/src/hotspot/share/gc/g1/g1FullGCScope.cpp index 3aef04b49e7..b4d3b365603 100644 --- a/src/hotspot/share/gc/g1/g1FullGCScope.cpp +++ b/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 */), diff --git a/src/hotspot/share/gc/g1/g1FullGCScope.hpp b/src/hotspot/share/gc/g1/g1FullGCScope.hpp index 2be5dec2666..c0035b9052a 100644 --- a/src/hotspot/share/gc/g1/g1FullGCScope.hpp +++ b/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; diff --git a/test/hotspot/jtreg/gc/g1/TestEagerReclaimHumongousRegionsLog.java b/test/hotspot/jtreg/gc/g1/TestEagerReclaimHumongousRegionsLog.java index 14102a0bbf1..9f671082b46 100644 --- a/test/hotspot/jtreg/gc/g1/TestEagerReclaimHumongousRegionsLog.java +++ b/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");