8356848: Separate Metaspace and GC printing

Reviewed-by: stefank, stuefe

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

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());

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());

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");

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> {
+class GCLogMessage : public FormatBuffer<512> {};
- public:
-  bool is_before;
-};
 
 template <>
-void EventLogBase<GCMessage>::print(outputStream* st, GCMessage& m) {
+void EventLogBase<GCLogMessage>::print(outputStream* st, GCLogMessage& m) {
-  st->print_cr("GC heap %s", m.is_before ? "before" : "after");
   st->print_raw(m);
 }
 
-class GCHeapLog : public EventLogBase<GCMessage> {
+class GCLog : public EventLogBase<GCLogMessage> {
- private:
+ protected:
-  void log_heap(CollectedHeap* heap, bool before);
+  virtual void log_usage(const CollectedHeap* heap, outputStream* st) const = 0;
 
  public:
-  GCHeapLog() : EventLogBase<GCMessage>("GC Heap History", "gc") {}
+  GCLog(const char* name, const char* handle) : EventLogBase<GCLogMessage>(name, handle) {}
 
-  void log_heap_before(CollectedHeap* heap) {
+  void log_gc(const CollectedHeap* heap, GCWhen::Type when);
-    log_heap(heap, true);
-  }
-  void log_heap_after(CollectedHeap* heap) {
-    log_heap(heap, false);
-  }
 };
 
-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):",
+  st.print("{");
-                 before ? "before" : "after",
-                 heap->total_collections(),
-                 heap->total_full_collections());
-
   {
+    heap->print_invocation_on(&st, _handle, when);
     StreamIndentor si(&st, 1);
-    heap->print_heap_on(&st);
+    log_usage(heap, &st);
-    MetaspaceUtils::print_on(&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() {
+void CollectedHeap::print_invocation_on(outputStream* st, const char* type, GCWhen::Type when) const {
-  LogTarget(Debug, gc, heap) lt;
+  st->print_cr("%s %s invocations=%u (full %u):", type, GCWhen::to_string(when), total_collections(), total_full_collections());
-  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_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) {
+  if (_metaspace_log != nullptr) {
-    _gc_heap_log->log_heap_before(this);
+    _metaspace_log->log_gc(this, when);
   }
 }
 
-void CollectedHeap::print_heap_after_gc() {
+void CollectedHeap::print_before_gc() const {
-  LogTarget(Debug, gc, heap) lt;
+  print_relative_to_gc(GCWhen::BeforeGC);
-  if (lt.is_enabled()) {
+}
-    LogStream ls(lt);
-    ls.print_cr("Heap after GC invocations=%u (full %u):", total_collections(), total_full_collections());
 
-    StreamIndentor si(&ls, 1);
+void CollectedHeap::print_after_gc() const {
-    print_heap_on(&ls);
+  print_relative_to_gc(GCWhen::AfterGC);
-    MetaspaceUtils::print_on(&ls);
-  }
-
-  if (_gc_heap_log != nullptr) {
-    _gc_heap_log->log_heap_after(this);
-  }
 }
 
 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;
   }
 }
 

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<mtGC> {
   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_before_gc() const;
-  void print_heap_after_gc();
+  void print_after_gc() const;
 
   // Registering and unregistering an nmethod (compiled code) with the heap.
   virtual void register_nmethod(nmethod* nm) = 0;

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

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;

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

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) {

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
+  // Take heap lock over heap, GC and metaspace printing so that information
-  // consistent.
+  // 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);
-      Universe::heap()->print_gc_on(st);
+    st->cr();
-      st->cr();
 
-      st->print_cr("Polling page: " PTR_FORMAT, p2i(SafepointMechanism::get_polling_page()));
+    st->print_cr("Polling page: " PTR_FORMAT, p2i(SafepointMechanism::get_polling_page()));
-      st->cr();
+    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);
   }
 

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\\):"),

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

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"));
     }