Summary

Separate Metaspace from GC in printing related code. There are already several locations where Metaspace is printed separately from GC so it would make sense to consolidate the information and print GC info from GC code and Metaspace from Metaspace code.

Problem

The reason Metaspace is also printed when printing GC-related info is becuase the permanent generation (PermGen) was historically part of the GC heap. In JDK-6964458, the PermGen was replaced by Metaspace, which uses native memory stored outside of the GC Heap. This raises the question if Metaspace should really be printed somewhere else. A strong argument behind keeping some of the current functionality is that the classes and nmethods in Metaspace is unloaded by the GC, so it makes sense to print information in connection to when a GC is performed.

Solution

To better reflect that Metaspace and GC are two separate things, their printing should be separated.

Metaspace should still be printed before/after a GC invocation/cycle, but using the metaspace UL tag and inside a separate ring-buffer. The before/after GC invocation prints are printed on debug level (-Xlog:gc*=debug) and the contents of the ring-buffer(s) are printed in hs_err files.

Not really a separation, but the instead of using gc+heap+exit as UL tags for exit printing, only gc+exit should be used to reflect that both the GC Heap and Metaspace is being printed, not just the heap. After discussion with GC and Sustaining engineers at Oracle, there is a desire to still have the Metaspace information during exit and not using the gc+metaspace+exit tags, as that would not align properly with the gc+heap+exit tags, which would break column alignment. A good compromise is to use the gc+exit tags for both GC Heap and Metaspace exit printing.

The areas where the printing should be separated are:

• In VMError reporting, i.e., hs_err files, VM.info jcmd and -XX:+PrintVMInfoAtExit flag. Metaspace can be moved from the "Heap:" section to the already existing "Metaspace:" section. Again, the same information is accessible, but from the Metaspace section instead.
• The GC.heap_info jcmd, where Metaspace printing can be moved to the already existing VM.metaspace jcmd. The same Metaspace information is still accessible, but from the Metaspace jcmd instead.

Specification

No information from printing has been removed, just moved to other places. No changes in printing-level, from info to debug or vice versa for example. Some log-tags have been changed, for example, from gc+heap to gc+metaspace in the before/after GC invocation printing and from gc+heap+exit to gc+exit.

PR: https://github.com/openjdk/jdk/pull/25214

Example Output - before/after GC invocation printing (-Xlog:gc*=debug)

Before and after prints the content but prefixed with "X before GC invocations=N" and "X after GC invocations=N". The examples below show just the before printing.

Before

[1,370s][debug][gc,heap     ] GC(0) Y: Heap before GC invocations=0 (full 0):
[1,370s][debug][gc,heap     ] GC(0) Y:  ZHeap           used 862M, capacity 862M, max capacity 9216M
[1,370s][debug][gc,heap     ] GC(0) Y:   Cache          0M (0)
[1,370s][debug][gc,heap     ] GC(0) Y:  Metaspace       used 18720K, committed 19008K, reserved 1114112K
[1,370s][debug][gc,heap     ] GC(0) Y:   class space    used 1611K, committed 1728K, reserved 1048576K

After:

[1,039s][debug][gc,heap     ] GC(0) Y: Heap Before GC invocations=0 (full 0):
[1,039s][debug][gc,heap     ] GC(0) Y:  ZHeap           used 860M, capacity 860M, max capacity 9216M
[1,039s][debug][gc,heap     ] GC(0) Y:   Cache          0M (0)
[1,039s][debug][gc,metaspace] GC(0) Y: Metaspace Before GC invocations=0 (full 0):
[1,039s][debug][gc,metaspace] GC(0) Y:  Metaspace       used 18674K, committed 19008K, reserved 1114112K
[1,039s][debug][gc,metaspace] GC(0) Y:   class space    used 1601K, committed 1728K, reserved 1048576K

and in hs_err file:

Before:

GC Heap History (250 events):
Event: 10,431 GC heap before
{Heap before GC invocations=241 (full 89):
 ZHeap           used 9216M, capacity 9216M, max capacity 9216M
  Cache          0M (0)
 Metaspace       used 18660K, committed 19008K, reserved 1114112K
  class space    used 1605K, committed 1728K, reserved 1048576K
}
...

After:

GC Heap Usage History (72 events):
Event: 1,005 {heap Before GC invocations=0 (full 0):
 ZHeap           used 860M, capacity 860M, max capacity 9216M
  Cache          0M (0)
}
...

Metaspace Usage History (72 events):
Event: 1,005 {metaspace Before GC invocations=0 (full 0):
 Metaspace       used 18671K, committed 19008K, reserved 1114112K
  class space    used 1601K, committed 1728K, reserved 1048576K
}
...

Example Output - jcmd

Before:

$ jcmd SourceLauncher GC.heap_info
71420:
 ZHeap           used 96M, capacity 576M, max capacity 9216M
  Cache          480M (1)
   size classes  256M (1)
 Metaspace       used 18155K, committed 18496K, reserved 1114112K
  class space    used 1536K, committed 1664K, reserved 1048576K

$ jcmd SourceLauncher VM.metaspace
71420:

Total Usage - 125 loaders, 2860 classes:
...

After:

$ jcmd SourceLauncher GC.heap_info
21832:
ZHeap            used 96M, capacity 576M, max capacity 9216M
 Cache           480M (1)
  size classes   256M (1)

$ jcmd SourceLauncher VM.metaspace
21832:
Metaspace        used 18134K, committed 18432K, reserved 1114112K
 class space     used 1519K, committed 1664K, reserved 1048576K

Total Usage - 125 loaders, 2834 classes:
...

Example output - exit printing

Before (-Xlog:gc+heap+exit=info):

[0,145s][info][gc,heap,exit] Heap
[0,145s][info][gc,heap,exit]  ZHeap           used 6M, capacity 576M, max capacity 9216M
[0,145s][info][gc,heap,exit]   Cache          570M (1)
[0,145s][info][gc,heap,exit]    size classes  512M (1)
[0,145s][info][gc,heap,exit]  Metaspace       used 7859K, committed 8000K, reserved 1114112K
[0,145s][info][gc,heap,exit]   class space    used 498K, committed 576K, reserved 1048576K

After (-Xlog:gc+exit=info):

[0,154s][info][gc,exit] Heap
[0,154s][info][gc,exit]  ZHeap           used 6M, capacity 576M, max capacity 9216M
[0,154s][info][gc,exit]   Cache          570M (1)
[0,154s][info][gc,exit]    size classes  512M (1)
[0,154s][info][gc,exit]  Metaspace       used 7810K, committed 8000K, reserved 1114112K
[0,154s][info][gc,exit]   class space    used 485K, committed 576K, reserved 1048576K

Example output - hs_err files:

Before:

Heap:
 ZHeap           used 6M, capacity 576M, max capacity 9216M
  Cache          570M (1)
   size classes  512M (1)
 Metaspace       used 7767K, committed 7936K, reserved 1114112K
  class space    used 494K, committed 576K, reserved 1048576K
...

Metaspace:

Usage:
  Non-class:      7,10 MB used.
      Class:    494,15 KB used.
       Both:      7,59 MB used.
...

After:

Heap:
 ZHeap           used 6M, capacity 576M, max capacity 9216M
  Cache          570M (1)
   size classes  512M (1)

...

Metaspace:
Metaspace        used 7742K, committed 7936K, reserved 1114112K
 class space     used 480K, committed 576K, reserved 1048576K

Usage:
  Non-class:      7,09 MB used.
      Class:    480,63 KB used.
       Both:      7,56 MB used.
...