From 85af573cb6b5063c24f1efcbfb80bbace2883c7c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joel=20Sikstr=C3=B6m?= Date: Tue, 27 May 2025 06:58:57 +0000 Subject: [PATCH] 8356848: Separate Metaspace and GC printing Reviewed-by: stefank, stuefe --- src/hotspot/share/gc/g1/g1CollectedHeap.cpp | 4 +- .../share/gc/parallel/psParallelCompact.cpp | 4 +- src/hotspot/share/gc/parallel/psScavenge.cpp | 4 +- src/hotspot/share/gc/serial/serialHeap.cpp | 8 +- src/hotspot/share/gc/shared/collectedHeap.cpp | 113 ++++++++++-------- src/hotspot/share/gc/shared/collectedHeap.hpp | 14 ++- src/hotspot/share/gc/z/zStat.cpp | 4 +- .../share/memory/metaspace/metaspaceDCmd.cpp | 2 + src/hotspot/share/runtime/java.cpp | 2 +- .../share/services/diagnosticCommand.cpp | 1 - src/hotspot/share/utilities/vmError.cpp | 28 ++--- .../ErrorHandling/ShowEventsOnCrashTest.java | 3 +- .../serviceability/dcmd/gc/HeapInfoTest.java | 12 +- .../serviceability/dcmd/vm/EventsTest.java | 8 +- 14 files changed, 118 insertions(+), 89 deletions(-) diff --git a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp index 6ea4e4f197f..49ec55cf74a 100644 --- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp +++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp @@ -2413,7 +2413,7 @@ G1HeapPrinterMark::G1HeapPrinterMark(G1CollectedHeap* g1h) : _g1h(g1h), _heap_tr _g1h->rem_set()->print_periodic_summary_info("Before GC RS summary", _g1h->total_collections(), true /* show_thread_times */); - _g1h->print_heap_before_gc(); + _g1h->print_before_gc(); _g1h->print_heap_regions(); } @@ -2427,7 +2427,7 @@ G1HeapPrinterMark::~G1HeapPrinterMark() { _heap_transition.print(); _g1h->print_heap_regions(); - _g1h->print_heap_after_gc(); + _g1h->print_after_gc(); // Print NUMA statistics. _g1h->numa()->print_statistics(); } diff --git a/src/hotspot/share/gc/parallel/psParallelCompact.cpp b/src/hotspot/share/gc/parallel/psParallelCompact.cpp index ed8df5d42f6..79a0b898a6b 100644 --- a/src/hotspot/share/gc/parallel/psParallelCompact.cpp +++ b/src/hotspot/share/gc/parallel/psParallelCompact.cpp @@ -664,7 +664,7 @@ void PSParallelCompact::pre_compact() CodeCache::on_gc_marking_cycle_start(); - heap->print_heap_before_gc(); + heap->print_before_gc(); heap->trace_heap_before_gc(&_gc_tracer); // Fill in TLABs @@ -1167,7 +1167,7 @@ bool PSParallelCompact::invoke_no_policy(bool clear_all_soft_refs) { Universe::verify("After GC"); } - heap->print_heap_after_gc(); + heap->print_after_gc(); heap->trace_heap_after_gc(&_gc_tracer); AdaptiveSizePolicyOutput::print(size_policy, heap->total_collections()); diff --git a/src/hotspot/share/gc/parallel/psScavenge.cpp b/src/hotspot/share/gc/parallel/psScavenge.cpp index c8996ec6d9d..7729b3e2006 100644 --- a/src/hotspot/share/gc/parallel/psScavenge.cpp +++ b/src/hotspot/share/gc/parallel/psScavenge.cpp @@ -352,7 +352,7 @@ bool PSScavenge::invoke(bool clear_soft_refs) { young_gen->eden_space()->accumulate_statistics(); } - heap->print_heap_before_gc(); + heap->print_before_gc(); heap->trace_heap_before_gc(&_gc_tracer); assert(!NeverTenure || _tenuring_threshold == markWord::max_age + 1, "Sanity"); @@ -587,7 +587,7 @@ bool PSScavenge::invoke(bool clear_soft_refs) { Universe::verify("After GC"); } - heap->print_heap_after_gc(); + heap->print_after_gc(); heap->trace_heap_after_gc(&_gc_tracer); AdaptiveSizePolicyOutput::print(size_policy, heap->total_collections()); diff --git a/src/hotspot/share/gc/serial/serialHeap.cpp b/src/hotspot/share/gc/serial/serialHeap.cpp index fdc710af02f..fae6acfcda9 100644 --- a/src/hotspot/share/gc/serial/serialHeap.cpp +++ b/src/hotspot/share/gc/serial/serialHeap.cpp @@ -404,7 +404,7 @@ bool SerialHeap::do_young_collection(bool clear_soft_refs) { GCTraceTime(Info, gc) t("Pause Young", nullptr, gc_cause(), true); TraceCollectorStats tcs(_young_gen->counters()); TraceMemoryManagerStats tmms(_young_gen->gc_manager(), gc_cause(), "end of minor GC"); - print_heap_before_gc(); + print_before_gc(); const PreGenGCValues pre_gc_values = get_pre_gc_values(); increment_total_collections(false); @@ -440,7 +440,7 @@ bool SerialHeap::do_young_collection(bool clear_soft_refs) { gc_epilogue(false); - print_heap_after_gc(); + print_after_gc(); return result; } @@ -623,7 +623,7 @@ void SerialHeap::do_full_collection(bool clear_all_soft_refs) { TraceCollectorStats tcs(_old_gen->counters()); TraceMemoryManagerStats tmms(_old_gen->gc_manager(), gc_cause(), "end of major GC"); const PreGenGCValues pre_gc_values = get_pre_gc_values(); - print_heap_before_gc(); + print_before_gc(); increment_total_collections(true); const bool should_verify = total_collections() >= VerifyGCStartAt; @@ -683,7 +683,7 @@ void SerialHeap::do_full_collection(bool clear_all_soft_refs) { // the initial value for "complete" flag. gc_epilogue(true); - print_heap_after_gc(); + print_after_gc(); if (should_verify && VerifyAfterGC) { Universe::verify("After GC"); diff --git a/src/hotspot/share/gc/shared/collectedHeap.cpp b/src/hotspot/share/gc/shared/collectedHeap.cpp index 11fb3e2d40b..6628df66cad 100644 --- a/src/hotspot/share/gc/shared/collectedHeap.cpp +++ b/src/hotspot/share/gc/shared/collectedHeap.cpp @@ -67,33 +67,24 @@ Klass* CollectedHeap::_filler_object_klass = nullptr; size_t CollectedHeap::_filler_array_max_size = 0; size_t CollectedHeap::_stack_chunk_max_size = 0; -class GCMessage : public FormatBuffer<1024> { - public: - bool is_before; -}; +class GCLogMessage : public FormatBuffer<512> {}; template <> -void EventLogBase::print(outputStream* st, GCMessage& m) { - st->print_cr("GC heap %s", m.is_before ? "before" : "after"); +void EventLogBase::print(outputStream* st, GCLogMessage& m) { st->print_raw(m); } -class GCHeapLog : public EventLogBase { - private: - void log_heap(CollectedHeap* heap, bool before); +class GCLog : public EventLogBase { + protected: + virtual void log_usage(const CollectedHeap* heap, outputStream* st) const = 0; public: - GCHeapLog() : EventLogBase("GC Heap History", "gc") {} + GCLog(const char* name, const char* handle) : EventLogBase(name, handle) {} - void log_heap_before(CollectedHeap* heap) { - log_heap(heap, true); - } - void log_heap_after(CollectedHeap* heap) { - log_heap(heap, false); - } + void log_gc(const CollectedHeap* heap, GCWhen::Type when); }; -void GCHeapLog::log_heap(CollectedHeap* heap, bool before) { +void GCLog::log_gc(const CollectedHeap* heap, GCWhen::Type when) { if (!should_log()) { return; } @@ -101,25 +92,39 @@ void GCHeapLog::log_heap(CollectedHeap* heap, bool before) { double timestamp = fetch_timestamp(); MutexLocker ml(&_mutex, Mutex::_no_safepoint_check_flag); int index = compute_log_index(); - _records[index].thread = nullptr; // Its the GC thread so it's not that interesting. + _records[index].thread = nullptr; // It's the GC thread so it's not that interesting. _records[index].timestamp = timestamp; - _records[index].data.is_before = before; stringStream st(_records[index].data.buffer(), _records[index].data.size()); - st.print_cr("{Heap %s GC invocations=%u (full %u):", - before ? "before" : "after", - heap->total_collections(), - heap->total_full_collections()); - + st.print("{"); { + heap->print_invocation_on(&st, _handle, when); StreamIndentor si(&st, 1); - heap->print_heap_on(&st); - MetaspaceUtils::print_on(&st); + log_usage(heap, &st); } - st.print_cr("}"); } +class GCHeapLog : public GCLog { + private: + void log_usage(const CollectedHeap* heap, outputStream* st) const override { + heap->print_heap_on(st); + } + + public: + GCHeapLog() : GCLog("GC Heap Usage History", "heap") {} +}; + +class GCMetaspaceLog : public GCLog { + private: + void log_usage(const CollectedHeap* heap, outputStream* st) const override { + MetaspaceUtils::print_on(st); + } + + public: + GCMetaspaceLog() : GCLog("Metaspace Usage History", "metaspace") {} +}; + ParallelObjectIterator::ParallelObjectIterator(uint thread_num) : _impl(Universe::heap()->parallel_object_iterator(thread_num)) {} @@ -163,36 +168,44 @@ bool CollectedHeap::contains_null(const oop* p) const { return *p == nullptr; } -void CollectedHeap::print_heap_before_gc() { - LogTarget(Debug, gc, heap) lt; - if (lt.is_enabled()) { - LogStream ls(lt); - ls.print_cr("Heap before GC invocations=%u (full %u):", total_collections(), total_full_collections()); +void CollectedHeap::print_invocation_on(outputStream* st, const char* type, GCWhen::Type when) const { + st->print_cr("%s %s invocations=%u (full %u):", type, GCWhen::to_string(when), total_collections(), total_full_collections()); +} +void CollectedHeap::print_relative_to_gc(GCWhen::Type when) const { + // Print heap information + LogTarget(Debug, gc, heap) lt_heap; + if (lt_heap.is_enabled()) { + LogStream ls(lt_heap); + print_invocation_on(&ls, "Heap", when); StreamIndentor si(&ls, 1); print_heap_on(&ls); + } + + if (_heap_log != nullptr) { + _heap_log->log_gc(this, when); + } + + // Print metaspace information + LogTarget(Debug, gc, metaspace) lt_metaspace; + if (lt_metaspace.is_enabled()) { + LogStream ls(lt_metaspace); + print_invocation_on(&ls, "Metaspace", when); + StreamIndentor indentor(&ls, 1); MetaspaceUtils::print_on(&ls); } - if (_gc_heap_log != nullptr) { - _gc_heap_log->log_heap_before(this); + if (_metaspace_log != nullptr) { + _metaspace_log->log_gc(this, when); } } -void CollectedHeap::print_heap_after_gc() { - LogTarget(Debug, gc, heap) lt; - if (lt.is_enabled()) { - LogStream ls(lt); - ls.print_cr("Heap after GC invocations=%u (full %u):", total_collections(), total_full_collections()); +void CollectedHeap::print_before_gc() const { + print_relative_to_gc(GCWhen::BeforeGC); +} - StreamIndentor si(&ls, 1); - print_heap_on(&ls); - MetaspaceUtils::print_on(&ls); - } - - if (_gc_heap_log != nullptr) { - _gc_heap_log->log_heap_after(this); - } +void CollectedHeap::print_after_gc() const { + print_relative_to_gc(GCWhen::AfterGC); } void CollectedHeap::print() const { @@ -301,9 +314,11 @@ CollectedHeap::CollectedHeap() : // Create the ring log if (LogEvents) { - _gc_heap_log = new GCHeapLog(); + _metaspace_log = new GCMetaspaceLog(); + _heap_log = new GCHeapLog(); } else { - _gc_heap_log = nullptr; + _metaspace_log = nullptr; + _heap_log = nullptr; } } diff --git a/src/hotspot/share/gc/shared/collectedHeap.hpp b/src/hotspot/share/gc/shared/collectedHeap.hpp index 8bf47d6b0bb..30ee35a34a7 100644 --- a/src/hotspot/share/gc/shared/collectedHeap.hpp +++ b/src/hotspot/share/gc/shared/collectedHeap.hpp @@ -48,9 +48,10 @@ class GCHeapLog; class GCHeapSummary; +class GCMemoryManager; +class GCMetaspaceLog; class GCTimer; class GCTracer; -class GCMemoryManager; class MemoryPool; class MetaspaceSummary; class ReservedHeapSpace; @@ -94,7 +95,8 @@ class CollectedHeap : public CHeapObj { friend class MemAllocator; private: - GCHeapLog* _gc_heap_log; + GCHeapLog* _heap_log; + GCMetaspaceLog* _metaspace_log; // Historic gc information size_t _capacity_at_last_gc; @@ -420,6 +422,8 @@ protected: virtual void initialize_serviceability() = 0; + void print_relative_to_gc(GCWhen::Type when) const; + public: void pre_full_gc_dump(GCTimer* timer); void post_full_gc_dump(GCTimer* timer); @@ -435,6 +439,8 @@ protected: // explicitly checks if the given memory location contains a null value. virtual bool contains_null(const oop* p) const; + void print_invocation_on(outputStream* st, const char* type, GCWhen::Type when) const; + // Print heap information. virtual void print_heap_on(outputStream* st) const = 0; @@ -454,8 +460,8 @@ protected: // Default implementation does nothing. virtual void print_tracing_info() const = 0; - void print_heap_before_gc(); - void print_heap_after_gc(); + void print_before_gc() const; + void print_after_gc() const; // Registering and unregistering an nmethod (compiled code) with the heap. virtual void register_nmethod(nmethod* nm) = 0; diff --git a/src/hotspot/share/gc/z/zStat.cpp b/src/hotspot/share/gc/z/zStat.cpp index a6b2bd0930d..45c77e68f0e 100644 --- a/src/hotspot/share/gc/z/zStat.cpp +++ b/src/hotspot/share/gc/z/zStat.cpp @@ -701,7 +701,7 @@ ZGenerationTracer* ZStatPhaseGeneration::jfr_tracer() const { } void ZStatPhaseGeneration::register_start(ConcurrentGCTimer* timer, const Ticks& start) const { - ZCollectedHeap::heap()->print_heap_before_gc(); + ZCollectedHeap::heap()->print_before_gc(); jfr_tracer()->report_start(start); @@ -716,7 +716,7 @@ void ZStatPhaseGeneration::register_end(ConcurrentGCTimer* timer, const Ticks& s jfr_tracer()->report_end(end); - ZCollectedHeap::heap()->print_heap_after_gc(); + ZCollectedHeap::heap()->print_after_gc(); const Tickspan duration = end - start; ZStatDurationSample(_sampler, duration); diff --git a/src/hotspot/share/memory/metaspace/metaspaceDCmd.cpp b/src/hotspot/share/memory/metaspace/metaspaceDCmd.cpp index 0ab83b44a76..e6943b8e2d3 100644 --- a/src/hotspot/share/memory/metaspace/metaspaceDCmd.cpp +++ b/src/hotspot/share/memory/metaspace/metaspaceDCmd.cpp @@ -58,6 +58,8 @@ MetaspaceDCmd::MetaspaceDCmd(outputStream* output, bool heap) : } void MetaspaceDCmd::execute(DCmdSource source, TRAPS) { + MetaspaceUtils::print_on(output()); + // Parse scale value. const char* scale_value = _scale.value(); size_t scale = 0; diff --git a/src/hotspot/share/runtime/java.cpp b/src/hotspot/share/runtime/java.cpp index 1079212a843..06c5fbce756 100644 --- a/src/hotspot/share/runtime/java.cpp +++ b/src/hotspot/share/runtime/java.cpp @@ -480,7 +480,7 @@ void before_exit(JavaThread* thread, bool halt) { Universe::heap()->stop(); // Print GC/heap related information. - Log(gc, heap, exit) log; + Log(gc, exit) log; if (log.is_info()) { LogStream ls_info(log.info()); Universe::print_on(&ls_info); diff --git a/src/hotspot/share/services/diagnosticCommand.cpp b/src/hotspot/share/services/diagnosticCommand.cpp index 17906520f5c..26a762fa109 100644 --- a/src/hotspot/share/services/diagnosticCommand.cpp +++ b/src/hotspot/share/services/diagnosticCommand.cpp @@ -413,7 +413,6 @@ void RunFinalizationDCmd::execute(DCmdSource source, TRAPS) { void HeapInfoDCmd::execute(DCmdSource source, TRAPS) { MutexLocker hl(THREAD, Heap_lock); Universe::heap()->print_heap_on(output()); - MetaspaceUtils::print_on(output()); } void FinalizerInfoDCmd::execute(DCmdSource source, TRAPS) { diff --git a/src/hotspot/share/utilities/vmError.cpp b/src/hotspot/share/utilities/vmError.cpp index 24d649e1f11..7d1b17d5deb 100644 --- a/src/hotspot/share/utilities/vmError.cpp +++ b/src/hotspot/share/utilities/vmError.cpp @@ -1203,7 +1203,6 @@ void VMError::report(outputStream* st, bool _verbose) { st->print_cr("Heap:"); StreamIndentor si(st, 1); Universe::heap()->print_heap_on(st); - MetaspaceUtils::print_on(st); st->cr(); } @@ -1220,6 +1219,7 @@ void VMError::report(outputStream* st, bool _verbose) { STEP_IF("printing metaspace information", _verbose && Universe::is_fully_initialized()) st->print_cr("Metaspace:"); + MetaspaceUtils::print_on(st); MetaspaceUtils::print_basic_report(st, 0); STEP_IF("printing code cache information", _verbose && Universe::is_fully_initialized()) @@ -1391,38 +1391,34 @@ void VMError::print_vm_info(outputStream* st) { } #endif - // Take heap lock over both heap and GC printing so that information is - // consistent. - { + // Take heap lock over heap, GC and metaspace printing so that information + // is consistent. + if (Universe::is_fully_initialized()) { MutexLocker ml(Heap_lock); // STEP("printing heap information") - if (Universe::is_fully_initialized()) { - GCLogPrecious::print_on_error(st); + GCLogPrecious::print_on_error(st); + { st->print_cr("Heap:"); StreamIndentor si(st, 1); Universe::heap()->print_heap_on(st); - MetaspaceUtils::print_on(st); st->cr(); } // STEP("printing GC information") - if (Universe::is_fully_initialized()) { - Universe::heap()->print_gc_on(st); - st->cr(); + Universe::heap()->print_gc_on(st); + st->cr(); - st->print_cr("Polling page: " PTR_FORMAT, p2i(SafepointMechanism::get_polling_page())); - st->cr(); - } - } + st->print_cr("Polling page: " PTR_FORMAT, p2i(SafepointMechanism::get_polling_page())); + st->cr(); - // STEP("printing metaspace information") + // STEP("printing metaspace information") - if (Universe::is_fully_initialized()) { st->print_cr("Metaspace:"); + MetaspaceUtils::print_on(st); MetaspaceUtils::print_basic_report(st, 0); } diff --git a/test/hotspot/jtreg/runtime/ErrorHandling/ShowEventsOnCrashTest.java b/test/hotspot/jtreg/runtime/ErrorHandling/ShowEventsOnCrashTest.java index e2c1e51c338..0c8646a4345 100644 --- a/test/hotspot/jtreg/runtime/ErrorHandling/ShowEventsOnCrashTest.java +++ b/test/hotspot/jtreg/runtime/ErrorHandling/ShowEventsOnCrashTest.java @@ -60,7 +60,8 @@ public class ShowEventsOnCrashTest { // Pattern match the hs_err_pid file. Pattern[] patterns = new Pattern[] { Pattern.compile("Compilation events \\([0-9]* events\\):"), - Pattern.compile("GC Heap History \\([0-9]* events\\):"), + Pattern.compile("GC Heap Usage History \\([0-9]* events\\):"), + Pattern.compile("Metaspace Usage History \\([0-9]* events\\):"), Pattern.compile("Dll operation events \\([0-9]* events\\):"), Pattern.compile("Deoptimization events \\([0-9]* events\\):"), Pattern.compile("Classes loaded \\([0-9]* events\\):"), diff --git a/test/hotspot/jtreg/serviceability/dcmd/gc/HeapInfoTest.java b/test/hotspot/jtreg/serviceability/dcmd/gc/HeapInfoTest.java index b2297552b35..bc8b2b80645 100644 --- a/test/hotspot/jtreg/serviceability/dcmd/gc/HeapInfoTest.java +++ b/test/hotspot/jtreg/serviceability/dcmd/gc/HeapInfoTest.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2015, 2016, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2015, 2025, 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 @@ -44,7 +44,15 @@ public class HeapInfoTest { public void run(CommandExecutor executor) { String cmd = "GC.heap_info"; OutputAnalyzer output = executor.execute(cmd); - output.shouldContain("Metaspace"); + + // All GCs have different strategies for printing similar information, + // which makes it hard to grep for anything substantial. However, all + // GCs print the string "used", so lets check for that to see if the + // jcmd printed something at all. + output.shouldContain("used"); + + output.shouldNotContain("Unknown diagnostic command"); + output.shouldHaveExitValue(0); } @Test diff --git a/test/hotspot/jtreg/serviceability/dcmd/vm/EventsTest.java b/test/hotspot/jtreg/serviceability/dcmd/vm/EventsTest.java index 9828a8990e0..5990419b45c 100644 --- a/test/hotspot/jtreg/serviceability/dcmd/vm/EventsTest.java +++ b/test/hotspot/jtreg/serviceability/dcmd/vm/EventsTest.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2019, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2019, 2025, 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 @@ -52,7 +52,8 @@ public class EventsTest { // Those are always printed even if the corresponding event log is empty. output.stdoutShouldMatch(buildHeaderPattern("Events")); output.stdoutShouldMatch(buildHeaderPattern("Compilation")); - output.stdoutShouldMatch(buildHeaderPattern("GC Heap History")); + output.stdoutShouldMatch(buildHeaderPattern("GC Heap Usage History")); + output.stdoutShouldMatch(buildHeaderPattern("Metaspace Usage History")); output.stdoutShouldMatch(buildHeaderPattern("Deoptimization")); output.stdoutShouldMatch(buildHeaderPattern("Classes unloaded")); } @@ -64,7 +65,8 @@ public class EventsTest { output.stdoutShouldNotMatch(buildHeaderPattern("Events")); output.stdoutShouldNotMatch(buildHeaderPattern("Compilation")); - output.stdoutShouldNotMatch(buildHeaderPattern("GC Heap History")); + output.stdoutShouldNotMatch(buildHeaderPattern("GC Heap Usage History")); + output.stdoutShouldNotMatch(buildHeaderPattern("Metaspace Usage History")); output.stdoutShouldNotMatch(buildHeaderPattern("Classes unloaded")); }