1. Background introduction

1.1 introduction to application background

1) Business features: the traffic peak is concentrated in the daytime, and the traffic is very low in the early morning.

2) Application features:

• Many core business interfaces are provided externally. After 6 a.m., the traffic increases gradually.
• In the early morning, we will run some data processing tasks through automatic scheduling, mainly the cache preheating of core business data [read from DB(mysql/es) and write to redis].

1.2. jdk Version (openjdk)

Since oracle announced that it would target enterprise users, the version after JDK 8 u191 needs to pay for a commercial license. Therefore, the company has switched to openjdk. The current application version is openjdk 1.8.0_272-b10.

Download address: https://github.com/AdoptOpenJDK/openjdk8-binaries/releases/tag/jdk8u272-b10

1.3 operation environment configuration

The application is deployed in the docker environment. Docker resource configuration:

• Physical machine: 64 bit
• cpu: 4 cores
• Memory: 8G

1.4. jvm startup parameter configuration

Because many core interfaces are provided externally, the application needs low response delay. G1 is naturally selected in the selection of garbage collector. The following is the specific startup parameter configuration:

• -20: + useg1gc [Select G1 garbage collector]
• -Xms4G [initial heap memory 4G]
• -Xmx4G [the maximum heap memory is 4G, and the initial and maximum settings are the same, so as to avoid the automatic capacity expansion of applications in the heap during operation and affect the service stability]
• -20: Metaspacesize = 256M [capacity expansion threshold of metadata space. The memory committed of metadata space means that if it exceeds 256M, mixed GC and capacity expansion will occur]
• -20: Maxmetaspacesize = 1G [maximum metadata space 1G]
• -20: Maxdirectmemorysize = 1G [this parameter directly interferes with the sun.nio.MaxDirectMemorySize property and limits the maximum direct memory available to NiO to 1G]
• -20: Initialbootclassloadermetaspacesize = 256M [the initial value of the metadata space allocated to each classloader is 256M]
• -20: + printgcdetails [print GC log]
• -20: + printgcdatestamps [print GC log with timestamp]
• -20: + printheapatgc [the memory usage of the heap before and after GC should be printed]
• -Xloggc:/data/logs/java/gc.log [storage path (prefix) of GC logs]
• -20: + usegclogfilerotation [enable rolling storage of GC log files]
• -20: Numberofgclogfiles = 5 [GC log files are reserved at most 5]
• -20: Gclogfilesize = 30M [the maximum size of each GC log file is 30M. If it exceeds 30M, a new file will be generated]
• -20: + heapdumponoutofmemoryerror [dump heap dump file in case of memory overflow]
• -XX:HeapDumpPath=/data/logs/java/heap_dump_%p.log [storage address of heap dump file]

2. gc log

2.1. gc log header

The beginning of the gc log file is as follows

OpenJDK 64-Bit Server VM (25.272-b10) for linux-amd64 JRE (1.8.0_272-b10), built on Oct 19 2020 11:11:12 by "openjdk" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
Memory: 4k page, physical 8388608k(4903852k free), swap 16777212k(14997524k free)
CommandLine flags: -XX:CompressedClassSpaceSize=536870912 -XX:GCLogFileSize=31457280 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/java/heap_dump_%p.log -XX:InitialBootClassLoaderMetaspaceSize=268435456 -XX:InitialHeapSize=4294967296 -XX:MaxDirectMemorySize=1073741824 -XX:MaxHeapSize=4294967296 -XX:MaxMetaspaceSize=1073741824 -XX:MetaspaceSize=268435456 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation 

There are three parts of information: version and environment, memory, and command line parameters. You can verify it through the source code fragment of hotspot.

Source code snippet - > ostream.cpp

// dump vm version, os version, platform info, build id,
// memory usage and command line flags into header
void gcLogFileStream::dump_loggc_header() {
  if (is_open()) {
    print_cr("%s", Abstract_VM_Version::internal_vm_info_string());// Virtual machine information
    os::print_memory_info(this); // Operating system memory information
    print("CommandLine flags: "); 
    CommandLineFlags::printSetFlags(this); // Print command line parameters
  }
}

Next, let's take a look at these three parts of information.

1) The first line is version and environment information

• Version information of virtual machine: openjdk 64 bit server VM (25.272-b10)
• Operating system information: linux-amd64
• JRE version: JRE (1.8.0_272-b10)
• JDK build information: build on Oct 19 2020 11:11:12 by "openjdk" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)

2) The second line is memory information

• Memory page size: 4K
• Physical memory: 8G(4.7G free), switching partition 16G(14.3G free)

3) The third line is the command line parameter information

There are some relationships and differences between these parameters and startup parameters. Some are the same as the startup parameter configuration, but convert the (G/M/K) value into bytes. The following two categories need to be focused on:

3.1) the meaning is the same, and the name changes

-20: Initialheapsize corresponds to - Xms in the startup parameters

-20: Maxheapsize corresponds to - Xmx in the startup parameters

3.2) not set in the startup parameters, but it appears here

3.2.1) -XX:+PrintGC

Source code snippet - > global.hpp

manageable(bool, PrintGC, false, "Print message at garbage collection") 
                           
manageable(bool, PrintGCDetails, false, "Print more details at garbage collection")   

It can be seen from here that the default values of PrintGC and PrintGCDetails parameters are false. It will be set to true only when it is configured on the command line. Because PrintGCDetails is configured for the display, it must be true.

Source code snippet - > arguments. CPP - > arguments:: parse_ each_ vm_ init_ arg()

// A lot of code is omitted
 else if (match_option(option, "-Xloggc:", &tail)) {
    // A lot of code is omitted
    FLAG_SET_CMDLINE(bool, PrintGC, true);
    FLAG_SET_CMDLINE(bool, PrintGCTimeStamps, true);
}
// A lot of code is omitted

It can be seen from here that if Xloggc is configured, PrintGC will also be set to true by default. Here is a detail. Call flag_ SET_ The CmdLine method sets a parameter value, which will be printed in CommandLine flags. If the value is directly assigned by other methods, the logic may run normally, but in
This parameter may not be reflected in CommandLine flags.

Note here that in addition to flag_ SET_ Besides the CmdLine method, there is FLAG_SET_ERGO and flag_ SET_ The parameters set by the MGMT method can also be printed. But by calling flag_ SET_ The parameters set by the DEFAULT method will not be printed because FLAG_SET_DEFAULT sets the parameter level to DEFAULT. In the implementation of CommandLineFlags::printSetFlags method, only non DEFAULT level parameters are printed.

3.2.2) several parameters related to metadata space
These parameters are highly correlated, so they are discussed together.

• -20: + usecompressedoops [enable object pointer compression. If an object references other objects, a reference pointer must be maintained. If this parameter is enabled, it means that the pointer can be compressed and compressed to 32 bits in 64 bit environment]
• -XX:+UseCompressedClassPointers [turn on class pointer compression. The object header of each java object in the heap will have a pointer to its class. If this parameter is turned on, it means that the pointer can be compressed and compressed to 32 bits in 64 bit environment. The premise for this parameter to take effect is that UseCompressedOops is turned on. In essence, the class pointer is just a special reference pointer, reference Is not an ordinary object, but a runtime object of a class]
• -XX:CompressedClassSpace Size=536870912 [the premise for this parameter to take effect is that if UseCompressedClassPointers is enabled, there will be no compressed class space if class pointer compression is not enabled. The compressed classspace stores the runtime objects of the class. Note that there will be a place to store the runtime objects of the class regardless of whether class pointer compression is enabled or not After compression, a separate continuous memory space will be opened up for storage and will not be shared with ordinary metadata space. The space opened up separately is called class_capacity, and the space shared by other metadata objects (methods, constant pools, etc.) is called non_class_capacity. The value of this parameter is 512M. As for why it is 512M, let's analyze the source code]

The above mainly introduces the specific meaning of these parameters that are not set in the startup command but are automatically set by the virtual machine. Next, through the source code, let's see why these parameters are set and how the parameter values are calculated.

a) On 64 bit machines, usecompressedcoops and UseCompressedClassPointers are enabled by default

Source code snippet - > arguments.cpp

void Arguments::set_ergonomics_flags() {
    // Part of the code is omitted
    #ifdef _LP64
    set_use_compressed_oops();
    // set_use_compressed_klass_ptrs() must be called after calling
    // set_use_compressed_oops().
    
    // Note parsing: set_use_compressed_oops must be called to enable usecompressedcoops before set_use_compressed_klass_ptrs can be called to enable UseCompressedClassPointers
    set_use_compressed_klass_ptrs();
    #endif // _LP64
    // Part of the code is omitted
}

void Arguments::set_use_compressed_oops() {
#ifndef ZERO
#ifdef _LP64
  // MaxHeapSize is not set up properly at this point, but
  // the only value that can override MaxHeapSize if we are
  // to use UseCompressedOops is InitialHeapSize.

  // Note analysis: at this logical point, MaxHeapSize(-Xmx) may not be set, so you can only use InitialHeapSize to assign value to max_heap_size
  size_t max_heap_size = MAX2(MaxHeapSize, InitialHeapSize);
  // If max_heap_size is less than the maximum threshold for turning on pointer compression (32G)
  if (max_heap_size <= max_heap_for_compressed_oops()) {
#if !defined(COMPILER1) || defined(TIERED)
    if (FLAG_IS_DEFAULT(UseCompressedOops)) {
      // Set the UseCompressedOops value to true and the parameter level to ERGO
      FLAG_SET_ERGO(bool, UseCompressedOops, true);
    }
#endif
  }  
  // Part of the code is omitted
#endif // _LP64
#endif // ZERO
}


// NOTE: set_use_compressed_klass_ptrs() must be called after calling
// set_use_compressed_oops().
void Arguments::set_use_compressed_klass_ptrs() {
#ifndef ZERO
#ifdef _LP64
  // UseCompressedOops must be on for UseCompressedClassPointers to be on.
  if (!UseCompressedOops) {
    // If usecompressedcoops is false and UseCompressedClassPointers is set to true, a warning message will be output, and then UseCompressedClassPointers will be set to false
    if (UseCompressedClassPointers) {
      warning("UseCompressedClassPointers requires UseCompressedOops");
    }
    FLAG_SET_DEFAULT(UseCompressedClassPointers, false);
  } else {
    // If you go here, it means that UseCompressedOops is true
    // FLAG_IS_DEFAULT is used to judge whether a parameter is a default level parameter, regardless of the parameter value
    // Because UseCompressedClassPointers is a default level parameter, you can use UseCompressedClassPointers
    if (FLAG_IS_DEFAULT(UseCompressedClassPointers)) {
      FLAG_SET_ERGO(bool, UseCompressedClassPointers, true);
    }
    // Next, check whether the CompressedClassSpaceSize setting is too large. If it is too large, UseCompressedClassPointers will still be closed. The runtime data structures of such classes are still stored in the metadata area and will not open up space separately.
    // Check the CompressedClassSpaceSize to make sure we use compressed klass ptrs.
    if (UseCompressedClassPointers) {
      if (CompressedClassSpaceSize > KlassEncodingMetaspaceMax) {
        warning("CompressedClassSpaceSize is too large for UseCompressedClassPointers");
        FLAG_SET_DEFAULT(UseCompressedClassPointers, false);
      }
    }
  }
#endif // _LP64
#endif // !ZERO
}

b) Value of CompressedClassSpaceSize

Source code snippet - > globals.hpp

product(uintx, CompressedClassSpaceSize, 1*G,"Maximum size of class area in Metaspace when compressed class pointers are used")  

The DEFAULT value of CompressedClassSpaceSize is 1G (the DEFAULT level is DEFAULT) However, whether this space will be opened depends on whether UseCompressedClassPointers is true. Through the source code analysis in a), it is known that usecompressedclasspacesize is open, but the value obtained in the GC log is 512M, not 1G, indicating that there are other calculation logic.

Source code snippet - > metaspace.cpp

void Metaspace::ergo_initialize() {
  
  // A lot of code is omitted

  CompressedClassSpaceSize = align_size_down_bounded(CompressedClassSpaceSize, _reserve_alignment);
  // By calling the set_compressed_class_space_size method, the current value of compressed classspacesize is copied and assigned to
  _compressed_class_space_size Variable.
  set_compressed_class_space_size(CompressedClassSpaceSize);

  // Virtualspacemoduliplier is a constant of 2, and the InitialBootClassLoaderMetaspaceSize is 256M configured through the startup parameter, so min_metaspace_sz (minimum metadata space) is 512M
  uintx min_metaspace_sz =
      VIRTUALSPACEMULTIPLIER * InitialBootClassLoaderMetaspaceSize;
  if (UseCompressedClassPointers) {
    // 1G is configured in the MaxMetaspaceSize startup parameter
    // (512M + 1g > 1g) is true
    if ((min_metaspace_sz + CompressedClassSpaceSize) >  MaxMetaspaceSize) {
      // If min_metaspace_sz is found to be greater than MaxMetaspaceSize, it indicates that the MaxMetaspaceSize configuration is too small, and the virtual machine will terminate and exit directly.
      // Therefore, the configuration value of MaxMetaspaceSize should be at least twice that of InitialBootClassLoaderMetaspaceSize
      if (min_metaspace_sz >= MaxMetaspaceSize) {
        vm_exit_during_initialization("MaxMetaspaceSize is too small.");
      } else {
        // Based on the startup parameter configuration mentioned above, the logic will go to this part
        // The CompressedClassSpaceSize will be reset to 1G - 512M = 512M
        FLAG_SET_ERGO(uintx, CompressedClassSpaceSize,
                      MaxMetaspaceSize - min_metaspace_sz);
      }
    }
  // If class pointer compression is not enabled and the minimum metadata space is found to be greater than the set maximum metadata space, set the initial metadata space to min_metaspace_sz  
  } else if (min_metaspace_sz >= MaxMetaspaceSize) {
    FLAG_SET_ERGO(uintx, InitialBootClassLoaderMetaspaceSize,
                  min_metaspace_sz);
  }

}

2.2. young gc log

Most of the gc logs of this application are young gc logs. Even if mixed gc occurs, there is at least one young gc in the whole mixed gc cycle. It can be roughly considered that mixed gc = various concurrent stages + interspersed n young gc + n mixed gc. Moreover, the format of gc logs marked as mixed is the same as that of young gc, except for various numbers Value. Therefore, focus on the fine analysis of the contents of young gc logs. While mixed gc focuses on the analysis of its various composition stages and recycling steps through gc logs. The following is a regular log fragment of young gc.

{Heap before GC invocations=302 (full 0):
 garbage-first heap   total 4194304K, used 3492794K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 1228 young (2514944K), 45 survivors (92160K)
 Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K
  class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K

// Gorgeous split line

2021-11-06T06:07:37.195+0800: 23577.357: [GC pause (G1 Evacuation Pause) (young), 0.1141917 secs]
   [Parallel Time: 97.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 23577359.3, Avg: 23577359.3, Max: 23577359.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 3.4, Avg: 4.5, Max: 7.6, Diff: 4.2, Sum: 18.0]
      [Update RS (ms): Min: 12.0, Avg: 14.7, Max: 15.7, Diff: 3.6, Sum: 58.9]
         [Processed Buffers: Min: 32, Avg: 69.8, Max: 98, Diff: 66, Sum: 279]
      [Scan RS (ms): Min: 0.4, Avg: 0.5, Max: 0.5, Diff: 0.0, Sum: 1.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [Object Copy (ms): Min: 77.2, Avg: 77.6, Max: 77.8, Diff: 0.6, Sum: 310.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.4]
      [GC Worker Total (ms): Min: 97.4, Avg: 97.4, Max: 97.5, Diff: 0.1, Sum: 389.8]
      [GC Worker End (ms): Min: 23577456.8, Avg: 23577456.8, Max: 23577456.8, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.8 ms]
   [Other: 15.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 9.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 1.5 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 3.7 ms]
   [Eden: 2366.0M(2366.0M)->0.0B(2372.0M) Survivors: 92160.0K->86016.0K Heap: 3410.9M(4096.0M)->1055.1M(4096.0M)]

// Gorgeous split line

Heap after GC invocations=303 (full 0):
 garbage-first heap   total 4194304K, used 1080394K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 42 young (86016K), 42 survivors (86016K)
 Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K
  class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K
}
 [Times: user=0.28 sys=0.13, real=0.12 secs] 

The log of a young gc can be divided into three parts: heap and metadata information before the start of gc, details of gc actions, and heap and metadata information after the end of gc

2.2.1 heap and metadata information before gc start

Heap before GC invocations=302 (full 0):
 garbage-first heap   total 4194304K, used 3492794K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 1228 young (2514944K), 45 survivors (92160K)
 Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K
  class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K

1) Recovery times

Heap before GC invocations=302 (full 0)

invocations=302 indicates that 302 garbage collections have been experienced before the start of this gc, of which full gc is 0.

2) Memory usage of heap

garbage-first heap   total 4194304K, used 3492794K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)

• For the heap before GC, the [reserved] memory is 4G in total, and 3492794K (about 3.3G) is used,
• There are three hexadecimal values in brackets. 0x-00000006e00000000: this value has 16 valid values in total. When converted to binary, it is 64 valid values (the CPU of the physical machine where the application is located is 64 bits)
  • The first value: 0x-00000006e00000000 refers to the low address boundary of heap reserved memory
  • The third value: 0x-00000007e00000000 refers to the heap reserved memory high address boundary
  • 6e00000000 = 01101111 + 28 zeros
  • 7e00000000 = 01111111 + 28 zeros
  • (7e00000000 - 6e00000000) = 1 + 32 zeros = 32nd power of 2 = 4G
    • Because the startup parameter - Xmx is set to 4G
  • The second value: 0x00000006e0204000. Generally speaking, it is the high address boundary of committed memory.
    • According to this statement, the result (this value - heap reserved memory low address boundary) should be approximately equal to the used value (3.5G).
    • Actually: 0x6e0204000 - 0x6e00000000 = 0x204000 = 2113536 (decimal value) ≈ 2.01M
      • This value is far from 3.5G. Therefore, this value cannot directly represent the committed memory. For this value, there is a separate analysis in Section 3) below.

region size 2048K, 1228 young (2514944K), 45 survivors (92160K)

For each region 2m, there are 1228 young region s (occupying 2514944K space), of which 45 are survivors (occupying 92160K space). During statistics, the regions of survivors are also included in the previous values.

3) What does the value of the intermediate address mean?

Source code snippet - > g1collectedheap.cpp

void G1CollectedHeap::print_on(outputStream* st) const {
  st->print(" %-20s", "garbage-first heap");
  st->print(" total " SIZE_FORMAT "K, used " SIZE_FORMAT "K",
            capacity()/K, used_unlocked()/K);
  // Focus on this line          
  st->print(" [" INTPTR_FORMAT ", " INTPTR_FORMAT ", " INTPTR_FORMAT ")",
            _hrm.reserved().start(),
            _hrm.reserved().start() + _hrm.length() + HeapRegion::GrainWords,
            _hrm.reserved().end());
  
  // Part of the code is omitted
}

From the above code, we can get

• _hrm.reserved().start() corresponds to 0x00000006e00000000
• _ hrm.reserved().end() corresponds to 0x00000007e00000000
• _ hrm.reserved().start() + _hrm.length() + HeapRegion::GrainWords corresponds to 0x00000006e0204000

So focus on analyzing the logic of the following line of code

_hrm.reserved().start() + _hrm.length() + HeapRegion::GrainWords

_ hrm.reserved().start() has made it clear that its value is 0x00000006e0000000, then_ What values are hrm.length() and HeapRegion::GrainWords?

Through RIH_ hrm.length()

Source code snippet - > heapregionmanager.hpp

// Return the number of regions that have been committed in the heap.
uint length() const { return _num_committed; }

You can see that his return value is_ num_committed. You can know from the annotation that this value represents the number of conditional region s in the heap.

Drill down to HeapRegion::GrainWords

Source code snippet - > heapregion. CPP - > heapregion:: Setup_ heap_ region_ size

GrainBytes = (size_t)region_size;
guarantee(GrainWords == 0, "we should only set it once");
GrainWords = GrainBytes >> LogHeapWordSize;

It can be seen that grainwords = GrainBytes > > LogHeapWordSize, where GrainBytes is region_size is 2M, and LogHeapWordSize is constant 3, that is, the last GrainWords = 2M/8.

From a macro point of view_ hrm.length() represents the number of committed regions, and GrainWords represents the size of regions, so the normal logic for calculating the reserved memory address should be

_hrm.reserved().start() + (_hrm.length() * HeapRegion::GrainWords)

Seems more reasonable. Regardless of this, if it is calculated according to the formula of the source code, it is still one_ The specific value of hrm.length() is not clear. So we can deduce it in reverse

_hrm.length() = 0x6e0204000 - _hrm.reserved().start() - HeapRegion::GrainWords

// Equivalent to
_hrm.length() = 0x6e0204000 - 0x6e0000000 - 2M/8  

If it is calculated directly according to the above equation, the value will be decimal 2097152. This is obviously wrong, because the maximum heap memory is 4G in total, and each region is 2M in size, that is, there can be 2048 regions at most. Moreover, the internal implementation of the virtual machine does not allow the allocation of more than 2048 regions, and the region and heap size will be automatically adjusted according to the upper limit of 2048. The reason why an incorrect number of committed regions is obtained above is that it is ignored_ hrm.reserved().start(), this_ hrm.reserved().start() returns a HeapWord *, which represents a pointer object in c + +. When the pointer object of c + + participates in numerical operation, it takes the memory address pointed to by the pointer, and other ordinary values calculated by it should be multiplied by a cardinality. This basis is 4 on a 32-bit machine and 8 on a 64 bit machine. Therefore, the intuitive and real calculation should be as follows

_hrm.length() * 8 = 0x6e0204000 - 0x6e0000000 - (2M/8 * 8)  = 16384 
// The equation is transformed as follows
_hrm.length() = 16384 / 8 = 2048

Therefore, we know that the number of committed regions is 2048. Although the memory used is only 3.3G, in fact, 4G memory has been divided into regions. Since all regions have been committed, if the memory address must be used to identify the high boundary of the committed memory address, it should be equal to 0x00000007e0000000. Therefore, the design and implementation logic of the hexadecimal number in the middle does bring some trouble to people.

4) Metadata space usage

Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K

Metaspace refers to the memory usage of the entire metadata space (including class space)

• used: the loaded data occupies 108m (about),
• capacity: chunks containing data occupy a total of 351624K (some blocks are not full). Each chunk is different based on level, and its size varies from 1K to 4m.
• committed: apply for a total space of 353612K for all chunk blocks (including the unused empty chunk blocks).
• Reserved: the reserved space requested from the operating system based on parameter settings when the jvm is started. Here is 1.5G (why 1.5? We'll talk about it later).

class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K

All of them will have a log line of class space because the UseCompressedClassPointers described above is enabled. If UseCompressedClassPointers is not enabled, there will be no such logs.

class space, as the name implies, stores the space of the class (class runtime structure, also known as Klass). Although it exists only when the class pointer compression is turned on, the class itself is not compressed. Because the class pointer in the object header of the object in the heap uses the 32-bit compression mechanism, the technical implementation requires that the corresponding class must be stored in a continuous storage space of no more than 4G (why?).

This is because when pointer compression is adopted, it is necessary to use (64 bit base address + 32-bit indexing) to address. If the target Klass is not within a continuous controllable space (continuous 4G [maximum memory range that can be identified by 32 bits]), it may produce: the address base address of a Klass > 32-bit representable value range, As a result, the compressed pointer cannot represent the target address and cannot reference the target class.

Although it can be considered that this space is independent, it is isolated from other data in the metadata space. However, the committed memory of the two-part space is still limited by MaxMetaSpaceSize.

If pointer compression is turned off, there will not be such a continuous independent space to store these Klass, which are interspersed and mixed with non Klass in metasapce.

From the specific values in the log, we can know that the total space occupied by Klass objects is only about 13M. However, the reserved memory space is 1G, which can be set through - XX:CompressedClassSpaceSize. The default is 1G, and the maximum internal limit of the jvm is 3G.

The problem is, in the parameters of CommandLine flags analyzed earlier, the compressed classspacesize is dynamically adjusted to 512M. Why is it reserved or 1G? As for why, we still need to look back at the code logic before the compressed classspacesize is modified to 512M.

a) How is the reserved memory of class space set?

Source code snippet - > metaspace.cpp

void Metaspace::ergo_initialize() {
  
  // A lot of code is omitted

  CompressedClassSpaceSize = align_size_down_bounded(CompressedClassSpaceSize, _reserve_alignment);
  // By calling set_ compressed_ class_ space_ The size method copies the current value of CompressedClassSpaceSize and assigns it to_ compressed_class_space_size variable.
  set_compressed_class_space_size(CompressedClassSpaceSize);ressedClassSpaceSize);

  // A lot of code is omitted
}  

void Metaspace::allocate_metaspace_compressed_klass_ptrs(char* requested_addr, address cds_base) {
    // A lot of code is omitted

    // compressed_class_space_size() Returns_ compressed_class_space_size
    ReservedSpace metaspace_rs = ReservedSpace(compressed_class_space_size(), _reserve_alignment,
    large_pages,requested_addr, 0);
    // A lot of code is omitted

    // Initialize class space
    initialize_class_space(metaspace_rs);

    // A lot of code is omitted
}

void Metaspace::initialize_class_space(ReservedSpace rs) {
   // A lot of code is omitted
   // _class_space_list
  _class_space_list = new VirtualSpaceList(rs);
  // A lot of code is omitted
}

_ compressed_class_space_size stores 1G. The development of reserved memory is also applied based on this value, so 1G is most reflected in the log.

b) How is the reserved memory of meta space set?

Source code snippet - > metaspace.cpp

void Metaspace::global_initialize() {

    // A lot of code is omitted

    // The call of this method is to allocate the memory of class space (concatenate the source code in part a above)
    allocate_metaspace_compressed_klass_ptrs(base, 0);


    // A lot of code is omitted

    // InitialBootClassLoaderMetaspaceSize was described earlier. It is set to 256M,
    // So:_ first_chunk_word_size =  256M/8
    _first_chunk_word_size = InitialBootClassLoaderMetaspaceSize / BytesPerWord;
    // _ first_chunk_word_size alignment
    _first_chunk_word_size = align_word_size_up(_first_chunk_word_size);
    
    // A lot of code is omitted
    // word_size = 2 * 256M / 8
    size_t word_size = VIRTUALSPACEMULTIPLIER * _first_chunk_word_size;
    // _ first_chunk_word_size is a power of 2
    word_size = align_size_up(word_size, Metaspace::reserve_alignment_words());

    // Initialize the list of virtual spaces.
    // Initialize meta space. word_ Although the size value is divided by 8, the final effect is 512M. The reason for dividing by 8 is to do numerical operations directly with the pointer address
    _space_list = new VirtualSpaceList(word_size);
}

As you can see from the source code above_ space_ The reserved memory of list is 512M. The following code is called when you want to print the reserved memory of the entire meta space

Source code snippet - > metaspace.cpp

void MetaspaceAux::print_on(outputStream* out) {
  Metaspace::MetadataType nct = Metaspace::NonClassType;

  out->print_cr(" Metaspace       "
                "used "      SIZE_FORMAT "K, "
                "capacity "  SIZE_FORMAT "K, "
                "committed " SIZE_FORMAT "K, "
                "reserved "  SIZE_FORMAT "K",
                used_bytes()/K,
                capacity_bytes()/K,
                committed_bytes()/K,
                reserved_bytes()/K); // Here's the point

  if (Metaspace::using_class_space()) {
    Metaspace::MetadataType ct = Metaspace::ClassType;
    out->print_cr("  class space    "
                  "used "      SIZE_FORMAT "K, "
                  "capacity "  SIZE_FORMAT "K, "
                  "committed " SIZE_FORMAT "K, "
                  "reserved "  SIZE_FORMAT "K",
                  used_bytes(ct)/K,
                  capacity_bytes(ct)/K,
                  committed_bytes(ct)/K,
                  reserved_bytes(ct)/K);
  }
}

class MetaspaceAux : AllStatic {
    // It can be seen here that_ space_list and_ class_ space_ The two parts of the list are added in reserved memory
    static size_t reserved_bytes() {
        return reserved_bytes(Metaspace::ClassType) +
            reserved_bytes(Metaspace::NonClassType);
    }
}

Combined with part a_ class_ space_ The reserved memory of list is 1G. Finally, the total reserved memory of the entire meta space is 512M + 1G = 1.5G.

2.2.2 details of gc execution

0) type of GC

2021-11-06T06:07:37.195+0800: 23577.357: [GC pause (G1 Evacuation Pause) (young), 0.1141917 secs]

At 6:07:37 a.m. on November 6, 2021, 23577.357 seconds (about 6 hours and 30 minutes) have passed since the jvm process was started [the pause caused by data migration for the younger generation took 0.114 seconds]
(young) refers to the younger generation gc. If mixed, it refers to the mixed gc (younger generation + older age)

(G1 evaluation pause) refers to the reason for this gc. The space usage reaches the threshold. If it is young gc, it means that the younger generation is full. If it is mixed gc, in most cases, the proportion of old age space in the whole heap space reaches the threshold (45% by default). This place may also be (G1 Humongous Allocation) indicating a giant object space allocation application. The memory allocation of each giant object will trigger a gc attempt. If it is already in the concurrent marking cycle stage, it will not actively initiate gc, otherwise it will actively initiate gc. Therefore, application development must pay attention to avoid generating giant objects.

There are many detailed steps in GC actions, some of which can be executed in parallel and some must be executed in serial. However, whether parallel or serial, multiple GC threads can work together.

1) Part of parallel execution

[Parallel Time: 97.6 ms, GC Workers: 4]

Multithreaded parallel recycling, a total of 4 worker threads, took 83.8 milliseconds

[GC Worker Start (ms): Min: 23577359.3, Avg: 23577359.3, Max: 23577359.4, Diff: 0.1]

The startup time of the four recycling threads (this is a numerical value, which refers to the millisecond time difference between the jvm process startup time point and the current time point)
Min is the earliest start, Max is the latest start, avg is the average start time, diff = max min

[Ext Root Scanning (ms): Min: 3.4, Avg: 4.5, Max: 7.6, Diff: 4.2, Sum: 18.0]

External root scanning (out of heap scanning): external roots include (JVM system directory, VM data structure, JNI thread handle, hardware register, global variable, thread stack root)

[Update RS (ms): Min: 12.0, Avg: 14.7, Max: 15.7, Diff: 3.6, Sum: 58.9]

Update RSET: each region maintains an RSET. When an external region references an object in this region, the card table index of the external region will be recorded.
However, the change of the reference information is to write to a queue synchronously, and then a separate thread (called concurrent optimization thread) reads the queue and updates the RSet asynchronously.
Therefore, it is possible that there are unprocessed change logs in the queue during garbage collection, so the RSet information is incomplete. Therefore, STW is required at this stage to check whether there are still unprocessed change records in the queue and update them to RSet.

[Processed Buffers: Min: 32, Avg: 69.8, Max: 98, Diff: 66, Sum: 279]

Processed buffer: refers to the change records in the queue that have not been consumed.

[Scan RS (ms): Min: 0.4, Avg: 0.5, Max: 0.5, Diff: 0.0, Sum: 1.9]

Scan the RSet of all region s to determine their internal survival objects.

[Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]

Code root scanning: it scans the reference of the code compiled by the JIT instant compiler to the region internal object of the heap.

[Object Copy (ms): Min: 77.2, Avg: 77.6, Max: 77.8, Diff: 0.6, Sum: 310.2]

Object migration: this step is to migrate the surviving objects to the new region and survivor, and some will be promoted to the old region. Recycle the old region.

[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

GC termination time: worker thread termination

[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]

Number of termination attempts: 1

[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.4]

This part is not the activity of GC, but the activity of JVM, which takes up the GC pause time (such as JNI compilation)

[GC Worker Total (ms): Min: 97.4, Avg: 97.4, Max: 97.5, Diff: 0.1, Sum: 389.8]

Total execution time of 4 recycle threads

[GC Worker End (ms): Min: 23577456.8, Avg: 23577456.8, Max: 23577456.8, Diff: 0.1]

The end time of the four recycle threads (this is a numerical value, which refers to the millisecond time difference between the jvm process startup time point and the current time point)

2) Serial execution part

[Code Root Fixup: 0.0 ms]

Code root correction: if the surviving object referenced by the code root is migrated from one region to another, its reference address to this object needs to be updated

[Code Root Purge: 0.0 ms]

Code root Cleanup: cleans up code that is no longer used in the code root

[Clear CT: 0.8 ms]

Clean up card table: clean up the scanned flag in the global card table

[Other: 15.8 ms]

Other operations are time consuming

[Choose CSet: 0.0 ms]

Select the collection to be recycled (this step is meaningful only when mixed recycling is used. Based on the consideration of pause time, heuristic algorithms should be used to redefine which regions need to be recycled. A simple young gc is all the younger generation regions)

[Ref Proc: 9.0 ms]

Reference processing: for soft references (recycled only when memory is insufficient), weak references (recyclable when gc occurs), virtual references, final references and JNI references

[Ref Enq: 0.0 ms]

References that can be recycled are queued.

[Redirty Cards: 0.2 ms]

The reference processing in the previous step will update the RSet information, so it is also necessary to synchronously mark the corresponding card table in the global bid opening as a dirty card

[Humongous Register: 1.5 ms]

Giant object registration (Statistics): Although giant objects are stored in older generation partitions, special optimization methods are also made in G1, and some giant object partitions will be recycled in young gc. When you are young gc, you will determine the external reference to yourself based on the RSet of the region.

Once the region corresponding to Rset is a Humongous region (hereinafter referred to as H-Region), it is found that the H-Region is no longer referenced through layer by layer reference checking. This means that the H-Region can be recycled.

[Humongous Reclaim: 0.1 ms]

Time consuming to recycle H-Region

[Free CSet: 3.7 ms]

Reclaim the space of regions in CSet and reset these regions to idle.

[Eden: 2366.0M(2366.0M)->0.0B(2372.0M) Survivors: 92160.0K->86016.0K Heap: 3410.9M(4096.0M)->1055.1M(4096.0M)]

Eden area: the total memory before recycling is 2366M, and 2366M is used. After recycling, the total memory increased by 6M to 2372M, but the used memory changed to OM because it has been recycled.

Surviving area: before recycling
90M memory is used, and 84M memory is used after recycling.

The whole heap space: the total memory is always 4G. 3410M is used before recycling and 1055M is used after recycling. The difference is 2355M, compared with 2366M emptied in Eden area and 8M reduced in survival area, there is a difference of 19M between them. It can be estimated that 19M data has been promoted to the old age.

2.2.3 heap and metadata information after gc

Heap after GC invocations=303 (full 0):
 garbage-first heap   total 4194304K, used 1080394K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 42 young (86016K), 42 survivors (86016K)
 Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K
  class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K

The meaning of this part of information has been described in detail in 2.2.1. The key point here is to compare the differences with some data before gc in 2.2.1.

1) Recovery times

invocations: 302 before gc and 303 here (after gc)

2) Memory usage of heap

The difference is only the value of used. Before gc, it was 3.3G, and here it is 1055M (a little more than 1G).
Pay attention to the value 0x00000006e0204000 in the middle of brackets. There is no change before and after gc. As for why there is no change, the origin of this value has been analyzed in detail in 2.2.1.

4) Metadata space usage

The statistical indicators of metadata space are no different from those before gc.

2.3 mixed gc log

As mentioned earlier, mixed gc is not a gc action, but a set of actions, including multiple steps and multiple gc. Let's look at a complete sample log of mixed gc.

{Heap before GC invocations=439 (full 0):
 garbage-first heap   total 4194304K, used 3719960K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 895 young (1832960K), 25 survivors (51200K)
 Metaspace       used 115155K, capacity 358590K, committed 358860K, reserved 1572864K
  class space    used 12989K, capacity 13737K, committed 13772K, reserved 1048576K
2021-11-06T14:24:22.132+0800: 53382.293: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0597538 secs]
   [Parallel Time: 51.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53382297.2, Avg: 53382297.2, Max: 53382297.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 5.2, Avg: 5.5, Max: 5.7, Diff: 0.5, Sum: 22.0]
      [Update RS (ms): Min: 7.1, Avg: 7.2, Max: 7.2, Diff: 0.1, Sum: 28.8]
         [Processed Buffers: Min: 52, Avg: 57.8, Max: 67, Diff: 15, Sum: 231]
      [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.0, Sum: 1.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 37.5, Avg: 37.8, Max: 38.1, Diff: 0.6, Sum: 151.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.5]
      [GC Worker Total (ms): Min: 50.8, Avg: 50.8, Max: 50.9, Diff: 0.1, Sum: 203.4]
      [GC Worker End (ms): Min: 53382348.0, Avg: 53382348.1, Max: 53382348.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 7.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.9 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 2.2 ms]
   [Eden: 1740.0M(1740.0M)->0.0B(1736.0M) Survivors: 51200.0K->51200.0K Heap: 3632.8M(4096.0M)->1896.8M(4096.0M)]
Heap after GC invocations=440 (full 0):
 garbage-first heap   total 4194304K, used 1942303K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 Metaspace       used 115155K, capacity 358590K, committed 358860K, reserved 1572864K
  class space    used 12989K, capacity 13737K, committed 13772K, reserved 1048576K
}
 [Times: user=0.16 sys=0.04, real=0.06 secs] 
2021-11-06T14:24:22.192+0800: 53382.353: [GC concurrent-root-region-scan-start]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-root-region-scan-end, 0.0567419 secs]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-mark-start]
2021-11-06T14:24:22.776+0800: 53382.938: [GC concurrent-mark-end, 0.5277478 secs]
2021-11-06T14:24:22.778+0800: 53382.939: [GC remark 2021-11-06T14:24:22.778+0800: 53382.939: [Finalize Marking, 0.0004157 secs] 2021-11-06T14:24:22.778+0800: 53382.940: [GC ref-proc, 1.2651008 secs] 2021-11-06T14:24:24.043+0800: 53384.205: [Unloading, 0.0628071 secs], 1.3315890 secs]
 [Times: user=1.33 sys=0.19, real=1.33 secs] 
2021-11-06T14:24:24.111+0800: 53384.272: [GC cleanup 1908M->1577M(4096M), 0.0058486 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-11-06T14:24:24.118+0800: 53384.279: [GC concurrent-cleanup-start]
2021-11-06T14:24:24.119+0800: 53384.280: [GC concurrent-cleanup-end, 0.0009447 secs]
{Heap before GC invocations=441 (full 0):
 garbage-first heap   total 4194304K, used 3380949K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 893 young (1828864K), 25 survivors (51200K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:26:53.067+0800: 53533.229: [GC pause (G1 Evacuation Pause) (young), 0.1490704 secs]
   [Parallel Time: 60.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53533231.3, Avg: 53533231.4, Max: 53533231.4, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 4.3, Avg: 5.2, Max: 7.3, Diff: 2.9, Sum: 20.8]
      [Update RS (ms): Min: 22.6, Avg: 24.2, Max: 25.1, Diff: 2.6, Sum: 96.9]
         [Processed Buffers: Min: 54, Avg: 69.0, Max: 104, Diff: 50, Sum: 276]
      [Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 20.1, Avg: 21.5, Max: 22.7, Diff: 2.6, Sum: 86.1]
      [Termination (ms): Min: 7.3, Avg: 8.6, Max: 10.4, Diff: 3.1, Sum: 34.5]
         [Termination Attempts: Min: 455, Avg: 509.0, Max: 567, Diff: 112, Sum: 2036]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [GC Worker Total (ms): Min: 59.9, Avg: 60.0, Max: 60.1, Diff: 0.3, Sum: 239.9]
      [GC Worker End (ms): Min: 53533291.3, Avg: 53533291.3, Max: 53533291.4, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 88.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 82.9 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 1.5 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 2.3 ms]
   [Eden: 1736.0M(1736.0M)->0.0B(154.0M) Survivors: 51200.0K->51200.0K Heap: 3301.7M(4096.0M)->1570.4M(4096.0M)]
Heap after GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1608107K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
 [Times: user=0.26 sys=0.07, real=0.14 secs] 
{Heap before GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1765803K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 102 young (208896K), 25 survivors (51200K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:27:05.068+0800: 53545.229: [GC pause (G1 Evacuation Pause) (mixed), 0.0407992 secs]
   [Parallel Time: 35.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53545230.0, Avg: 53545230.1, Max: 53545230.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.1, Avg: 2.5, Max: 3.3, Diff: 1.3, Sum: 10.0]
      [Update RS (ms): Min: 4.0, Avg: 4.4, Max: 4.6, Diff: 0.6, Sum: 17.8]
         [Processed Buffers: Min: 32, Avg: 48.2, Max: 59, Diff: 27, Sum: 193]
      [Scan RS (ms): Min: 2.8, Avg: 3.1, Max: 3.4, Diff: 0.6, Sum: 12.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 1.1]
      [Object Copy (ms): Min: 24.5, Avg: 24.9, Max: 25.1, Diff: 0.6, Sum: 99.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 35.2, Avg: 35.2, Max: 35.3, Diff: 0.1, Sum: 140.9]
      [GC Worker End (ms): Min: 53545265.3, Avg: 53545265.3, Max: 53545265.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 5.2 ms]
      [Choose CSet: 0.4 ms]
      [Ref Proc: 1.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.8 ms]
   [Eden: 154.0M(154.0M)->0.0B(188.0M) Survivors: 51200.0K->16384.0K Heap: 1724.4M(4096.0M)->1145.9M(4096.0M)]
Heap after GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1173387K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
 [Times: user=0.13 sys=0.02, real=0.04 secs] 
{Heap before GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1365899K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 102 young (208896K), 8 survivors (16384K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:27:20.626+0800: 53560.788: [GC pause (G1 Evacuation Pause) (mixed), 0.1076664 secs]
   [Parallel Time: 101.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53560789.1, Avg: 53560789.1, Max: 53560789.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.2, Avg: 2.5, Max: 2.7, Diff: 0.5, Sum: 9.8]
      [Update RS (ms): Min: 15.1, Avg: 15.1, Max: 15.1, Diff: 0.0, Sum: 60.5]
         [Processed Buffers: Min: 57, Avg: 70.8, Max: 85, Diff: 28, Sum: 283]
      [Scan RS (ms): Min: 11.7, Avg: 12.3, Max: 12.9, Diff: 1.3, Sum: 49.1]
      [Code Root Scanning (ms): Min: 0.4, Avg: 1.0, Max: 1.5, Diff: 1.1, Sum: 4.0]
      [Object Copy (ms): Min: 65.4, Avg: 66.1, Max: 66.9, Diff: 1.4, Sum: 264.6]
      [Termination (ms): Min: 4.3, Avg: 4.7, Max: 5.3, Diff: 1.1, Sum: 18.8]
         [Termination Attempts: Min: 408, Avg: 490.0, Max: 617, Diff: 209, Sum: 1960]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 101.6, Avg: 101.7, Max: 101.7, Diff: 0.1, Sum: 406.7]
      [GC Worker End (ms): Min: 53560890.7, Avg: 53560890.8, Max: 53560890.8, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 5.4 ms]
      [Choose CSet: 0.5 ms]
      [Ref Proc: 1.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.7 ms]
   [Eden: 188.0M(188.0M)->0.0B(2440.0M) Survivors: 16384.0K->16384.0K Heap: 1333.9M(4096.0M)->859.0M(4096.0M)]
Heap after GC invocations=444 (full 0):
 garbage-first heap   total 4194304K, used 879616K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
 [Times: user=0.36 sys=0.06, real=0.10 secs] 

In order to observe the steps of the whole mixed gc from a macro perspective, we omit some details in the gc pause type log, because the internal specific content format is consistent with the format of young gc we introduced earlier.
The simplified contents are as follows:

{
Heap before GC...    
2021-11-06T14:24:22.132+0800: 53382.293: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0597538 secs]
...
[Eden: 1740.0M(1740.0M)->0.0B(1736.0M) Survivors: 51200.0K->51200.0K Heap: 3632.8M(4096.0M)->1896.8M(4096.0M)]
Heap after GC invocations=440 (full 0):
 garbage-first heap   total 4194304K, used 1942303K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
  ...  
}
 [Times: user=0.16 sys=0.04, real=0.06 secs] 
 
// Gorgeous split line: This is a young gc, but the key point is that it is marked with initial mark, indicating that this is the beginning of a concurrent marking cycle.

2021-11-06T14:24:22.192+0800: 53382.353: [GC concurrent-root-region-scan-start]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-root-region-scan-end, 0.0567419 secs]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-mark-start]
2021-11-06T14:24:22.776+0800: 53382.938: [GC concurrent-mark-end, 0.5277478 secs]
2021-11-06T14:24:22.778+0800: 53382.939: [GC remark 2021-11-06T14:24:22.778+0800: 53382.939: [Finalize Marking, 0.0004157 secs] 2021-11-06T14:24:22.778+0800: 53382.940: [GC ref-proc, 1.2651008 secs] 2021-11-06T14:24:24.043+0800: 53384.205: [Unloading, 0.0628071 secs], 1.3315890 secs]
 [Times: user=1.33 sys=0.19, real=1.33 secs] 
2021-11-06T14:24:24.111+0800: 53384.272: [GC cleanup 1908M->1577M(4096M), 0.0058486 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-11-06T14:24:24.118+0800: 53384.279: [GC concurrent-cleanup-start]
2021-11-06T14:24:24.119+0800: 53384.280: [GC concurrent-cleanup-end, 0.0009447 secs]

// Gorgeous split line: the steps here are concurrent marking, re marking and concurrent cleaning. This also indicates that a concurrent marking cycle is over.

{
Heap before GC...    
2021-11-06T14:26:53.067+0800: 53533.229: [GC pause (G1 Evacuation Pause) (young), 0.1490704 secs]
...
[Eden: 1736.0M(1736.0M)->0.0B(154.0M) Survivors: 51200.0K->51200.0K Heap: 3301.7M(4096.0M)->1570.4M(4096.0M)]
Heap after GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1608107K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 ...  
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]
 
// Gorgeous split line: This is a simple young gc, which only cleans up the young generation.

{
Heap before GC...    
2021-11-06T14:27:05.068+0800: 53545.229: [GC pause (G1 Evacuation Pause) (mixed), 0.0407992 secs]
...
[Eden: 154.0M(154.0M)->0.0B(188.0M) Survivors: 51200.0K->16384.0K Heap: 1724.4M(4096.0M)->1145.9M(4096.0M)]
Heap after GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1173387K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 ...  
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]
 
// Gorgeous split line: This is a mixed gc, the younger generation and the older generation are cleaned up

{
Heap before GC...    
2021-11-06T14:27:20.626+0800: 53560.788: [GC pause (G1 Evacuation Pause) (mixed), 0.1076664 secs]
...
[Eden: 188.0M(188.0M)->0.0B(2440.0M) Survivors: 16384.0K->16384.0K Heap: 1333.9M(4096.0M)->859.0M(4096.0M)]
Heap after GC invocations=444 (full 0):
 garbage-first heap   total 4194304K, used 879616K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
... 
}
 [Times: user=0.36 sys=0.06, real=0.10 secs] 
 
// Gorgeous split line: This is also a mixed gc, and the young and old generations have been cleaned up. 

// The next log is an ordinary young gc. Therefore, it is considered that the end of the mixed gc log above is the end of a complete mixed recycling.

A complete mixed gc process starts with (young) (initial mark) and ends with (mixed).
Which mixed log ends? Look back from the initial mark. The first GC pause found is a mixed log. If the mixed gc pause log is not a mixed log, it means that the mixed log is the end of the mixed gc process.
The whole mixed gc process consists of several parts: concurrent marking cycle (1 or N) + ordinary young gc (0 or more times) + mixed recycling cycle

2.3.1 concurrent marking cycle

From (young) (initial mark) to GC concurrent cleanup end

1. Initial mark:

GC pause (G1 Evacuation Pause) (young) (initial-mark)
The start step of the concurrent marking cycle must be generated together with a young gc. What the initial tag does is tag the root node. This step requires STW, which can be done together with young gc, because young gc is also STW, which is equivalent to taking a ride.

2. Concurrent root region root partition scanning:

After the initial marking is completed, it means that a young gc is completed, and the surviving objects are transferred to the survivor partition. Then, the objects of these survivor partitions are survival objects, and they will be marked as root objects. This process is called root partition scanning. In fact, the survivor partitions are scanned. Because this process scans the survivor partition, it cannot be performed at the same time as the young gc, because the young gc will cause changes to the survivor partition.

3. Concurrent Marking:

Concurrent marking and application threads execute concurrently. This process scans older generations and marks reachable objects.

4. GC remark relabel:

STW. This process processes unprocessed logs that reference the change log buffer. At the same time, [GC ref proc] reference processing is also part of the relabeling phase. This step can be executed in parallel with multiple threads.

5. GC cleanup exclusive Cleanup:

Following the re marking, it is still STW at this time. At the same time, three things will be done in this step:

• RSET sorting: heuristic algorithm or define different levels of partitions according to RSET size. (the larger the RSET size, the more references to this partition, and the higher the level of this partition.)
• Sorting out heap partitions: for the partitions of the older generation, region s with high recovery income are identified based on the release of space and pause goals.
• Identify all free partitions: mark those internal objects as non viable partitions.

6. GC concurrent cleanup concurrent Cleanup:

The recycle thread and the application execute concurrently, and the partition marked as idle in the previous step is recycled.

2.3.2. Mixed recovery cycle

In the concurrent marking cycle described above, although GC concurrent cleanup (GC concurrent cleanup) is also experienced, it only cleans up the idle partitions where none of the objects survive. For the younger and older generations that some objects survive, the partition has not carried out data migration and partition cleaning. However, it has been identified which partitions should be recycled in the concurrent marking cycle, so the next is the GC pause action, which will include one or more GC pauses. The last GC pause is of type mixed. Simple young gc can also occur in the mixed recovery cycle.

In our example above, the mixed recovery cycle includes one young gc and two mixed gc.

{
Heap before GC...    
2021-11-06T14:26:53.067+0800: 53533.229: [GC pause (G1 Evacuation Pause) (young), 0.1490704 secs]
...
[Eden: 1736.0M(1736.0M)->0.0B(154.0M) Survivors: 51200.0K->51200.0K Heap: 3301.7M(4096.0M)->1570.4M(4096.0M)]
Heap after GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1608107K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 ...  
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]

This is a simple young gc, which only cleans up the young generation. The reactor space is reduced from 3301M to 1570M.

{
Heap before GC...    
2021-11-06T14:27:05.068+0800: 53545.229: [GC pause (G1 Evacuation Pause) (mixed), 0.0407992 secs]
...
[Eden: 154.0M(154.0M)->0.0B(188.0M) Survivors: 51200.0K->16384.0K Heap: 1724.4M(4096.0M)->1145.9M(4096.0M)]
Heap after GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1173387K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 ...  
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]

This is a mixed collection. Both the young generation and the old generation are cleaned up, but only 154M is used before the young generation is cleaned up. After cleaning, the whole heap space is reduced from 1724M to 1145M. We can estimate that even if the young generation are cleaned up, the heap space is reduced to 1570M, compared with 1145M at present, so the space released by the old generation should be > = 425m.

{
Heap before GC...    
2021-11-06T14:27:20.626+0800: 53560.788: [GC pause (G1 Evacuation Pause) (mixed), 0.1076664 secs]
...
[Eden: 188.0M(188.0M)->0.0B(2440.0M) Survivors: 16384.0K->16384.0K Heap: 1333.9M(4096.0M)->859.0M(4096.0M)]
Heap after GC invocations=444 (full 0):
 garbage-first heap   total 4194304K, used 879616K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
... 
}
 [Times: user=0.36 sys=0.06, real=0.10 secs] 

This is the second mixed collection. Both the young generation and the old generation were cleaned. Only 188M was used before the young generation was cleaned. After cleaning, the whole heap space was reduced from 1334M to 859M, and at least 287M was cleaned in the old age.

3. References

https://www.cnblogs.com/bjkandy/p/13877598.html
https://www.shangmayuan.com/a/d396bf8d18d94696a426a1ba.html
https://blog.csdn.net/zhanggang807/article/details/46011341