In-depth understanding of G1 GC logs

This article translated from: www.redhat.com/en/blog/col…

This article delves into G1 logging and tuning parameters. In order to tune G1 in the real world, you as a developer need to understand each step of the G1 garbage collector and the role each step plays in the overall garbage collection cycle. For the reader’s convenience, this article divides G1 logging parameters into three increments. This article will describe the role of each parameter and the tuning scenarios.

1. Basic parameters – These parameters must be used to use the G1 collector in production
2. Advanced parameters – These parameters need to be used to tune for certain problems as your application matures or the business load increases.
3. Debug parameters – These parameters are used to solve specific performance problems. If a problem cannot be rectified in a non-production environment, these parameters are used to troubleshoot problems in the production environment.

Basic parameters

If you are going to use THE G1 GC in a production environment, the following log-related parameters are required to troubleshoot basic garbage collection problems.

Use -xx :GCLogFileSize to set the appropriate GC log file size, -xx :NumberOfGCLogFiles to set the NumberOfGCLogFiles to keep, -xloggc :/path/to/gc.log to set the location of GC log files, Use the above three parameters to save GC logs during application running. I recommend saving GC logs for at least one week to provide sufficient runtime information for troubleshooting.

Cenozoic collection

Like other garbage collectors, G1 prints a detailed garbage collection log using -xx :PrintGCDetails. The following diagram shows the standard process for new generation collection, which I’ve broken down into six steps:

1. Four key messages
   • The generation of garbage collection occurred whenThe T10:2016-12-12 bronze. 811-0500, by setting-XX:+PrintGCDateStampsParameters can be printed out for this time;
   • Relative time after JVM startup – 25.959
   • This collection type, The New generation collection, will only collect the Eden partition
   • The collection took 0.0305171s, or 30ms
2. Lists the detailed process of parallel collection in the New generation collection
   • Parallel Time: STW (Stop The World) Time caused by a Parallel collection task during its operation. It takes 26.6ms from The start of The new generation garbage collection to The end of The last task
   • GC Workers: There are 4 threads responsible for garbage collection, through the parameter-XX:ParallelGCThreadsThe value of this parameter depends on the CPU. If the number of threads supported by the physical CPU is less than 8, the maximum value is 8. If the number of threads supported by the physical CPU is greater than 8, the default value is number x 5/8
   • GC Worker Start: The time (min) that has elapsed since the JVM started when the first garbage collection thread starts working; The time elapsed since the JVM started when the last garbage collection thread started (Max); Diff represents the difference between min and Max. Ideally, you want them to start almost at the same time, with diff approaching zero.
   • Ext Root Scanning: Time spent Scanning the Root collection (thread stacks, JNI, global variables, system tables, etc.), which is the starting point for garbage collection, trying to find if any nodes in the Root collection point to the current collection (CSet)
   • Update RS(Remembered Set or RSet): Each partition has its own RSet, which records Pointers to the current partition from other partitions. If the RSet is updated, a post-write barrier in G1 manages cross-partition references — new referenced cards are marked as dirty and put into a log buffer. If the log buffer is full, it is added to a global buffer, and there are threads concurrently processing the dirty card of the global log buffer during JVM running.Update RSIndicates that the garbage collection thread is allowed to process the log buffer that was not processed before the garbage collection began, which ensures that the RSet of the current partition is up to date.
     • Processed Buffers, which indicates how many log Buffers are Processed during Update RS.
   • Scan RS: Scans the RSet of each new generation partition to find out how many references to the current partition are from the CSet.
   • Code Root Scanning: Time spent Scanning Root nodes (local variables) in Code
   • Object Copy: During the evacuation pause, all partitions in the CSet must be moved and evacuated. The Object Copy is responsible for copying the surviving objects in the current partition to the new partition.
   • Termination: When a garbage collector thread completes a task, it will enter a critical section and try to help other garbage threads complete the task (Steal Outstanding Tasks). Min indicates when the garbage collector thread tries terminatie. Max indicates when the garbage collection thread is actually terminated.
     • Termination Attempts: If a garbage collection thread succeeds in stealing tasks from other threads, it either steals more tasks or Attempts terminate again, which increases each time terminate is resumed.
   • GC Worker Other: Time when the garbage collector thread is working on Other tasks
   • GC Worker Total: Shows minimum, maximum, average, difference, and Total time for each garbage collection thread.
   • GC Worker End: min indicates the time since the JVM started when the earliest garbage collection thread terminates; Max represents the time since the JVM was started when the last garbage collection thread ended. Ideally, you want them to end quickly, and ideally at the same time.
3. Some of the tasks in the New generation GC are listed:
   • Code Root Fixup: Free the data structure used to manage parallel garbage collection activities, should be close to 0, this step is performed linearly;
   • Code Root Purge: Purge more data structures, should be fast, take close to zero time, and also perform linearly.
   • Clear CT: Clears card tables
4. Contains some extended features
   • Choose CSet: Select the partition to be recycled and put it in the CSet (G1 chooses the partition with the most garbage first, that is, the partition with the lowest survival rate)
   • Ref Proc: Handles various references in Java — soft, weak, final, Phantom, JNI, etc.
   • Ref Enq: Iterate over all references and place those that cannot be reclaimed into the Pending list
   • Redirty Card: Cards that are modified during recycling will be reset as dirty
   • Humongous Register: JDK8u60 provides a feature that allows large objects to be recycled during new generation collections — throughG1ReclaimDeadHumongousObjectsAtYoungGCSet to true by default.
   • Humongous Reclaim: Time to do the following tasks: Ensure that the giant object can be reclaimed, release the partition occupied by the giant object, reset the partition type, return the partition to the free list, and update the free space.
   • Free CSet: The partition to be freed is returned to the Free list.
5. Shows the size variation of different generations, as well as the adaptive adjustment of heap size.
   • Eden: 1097.0m -> 0.0b (967.0m) : (1) The current generation generation collection is triggered because Eden space is full, so 1097M is allocated and 1097M is used; (2) All Eden partitions are evacuated, and the usage size of Eden partition becomes 0.0B after the end of the Cenozoic era; (3) The size of Eden partition is reduced to 967.0m
   • Survivors: 13.0m -> 139.0m: Due to the recovery treatment of the younger generation, survivor space increased from 13.0m to 139.0m;
   • Heap: 1694.4m (2048.0m)-> 736.3m (2048.0m) : (1) At the beginning of this garbage collection activity, the total Heap space usage is 1694.4m, the maximum Heap space is 2048M; (2) After this garbage collection, the heap space usage is 763.4m, and the maximum value remains unchanged.
6. Point 6 shows the garbage collection time of this new generation
   • User =0.8: CPU time consumed by the garbage collection thread in the new generation garbage collection process. This time is related to the number of garbage collection threads and may be much larger than real time.
   • Sys =0.0: CPU time consumed by kernel threads -real=0.03: actual time consumed by this garbage collection;

Concurrent garbage collection

The second collection activity in G1 is concurrent garbage collection. Concurrent garbage collection triggers many different conditions, but does the same thing. Its log is shown below:

1. Marks the beginning of the concurrent garbage collection phase:

   • GC Pause (G1 Evacuation pause)(Young)(initial-mark) : To take full advantage of STW opportunities to trace all reachable (survivable) objects, the initial-Mark phase exists as part of the New generation garbage collection (hitchhiking). Initial-mark sets up two TAMS (top-at-mark-start) variables to distinguish surviving objects from newly allocated objects in the concurrent marking phase. All objects prior to TAMS are considered alive during the current cycle.

2. Represents the first thing done in the first concurrent markup phase: a root partition scan

   • GC concurrent-root-region-scan-start: The root partition scan starts. The root partition scan mainly scans the new survivor partitions and finds references from objects in these partitions to the current partition. If any references are found, a record is made.
   • GC concurrent-root-region-scan-end: indicates that the root partition scan is complete, which takes 0.0030613 seconds

3. Represents the concurrent marking phase

   • GC Concurrent-mark-start: Concurrent marking phase begins. (1) The thread in the concurrent marking stage is run together with the application thread and does not STW, so it is called concurrent; Concurrent tag phase garbage collection threads. The default value is 25% of the number of Parallel threads. This value can also be used as an argument-XX:ConcGCThreadsSettings; (2) Trace the entire heap and use a bitmap to mark all surviving objects. Since objects before top TAMS are implicitly surviving, only those after top TAMS and before the threshold need to be marked; (3) Record the changes in the concurrent marking phase. G1 uses SATB algorithm, which requires a snapshot of the heap at the beginning of garbage collection. This snapshot is unchanged during garbage collection, but in fact some object references must change. G1 uses the pre-write barrier to record the change, and stores the record in a SATB buffer. If the buffer is full, it is added to a global buffer, and G1 has a thread processing the global buffer in parallel. (4) In the process of concurrent marking, the ratio of surviving objects in each partition to the size of the whole partition will be recorded;
   • GC concurrent-mark-end: indicates the end of the Concurrent marking phase, which takes 0.3055438 seconds

4. Re-marking the phase will Stop the World

   • Finalize Marking: Finalizer The Finalizer object in the Finalize Marking: Finalizer list takes 0.0014099 seconds.
   • GC ref-proc: reference processing (soft, weak, final, phantom, JNI, etc.) takes 0.0000480s;
   • 2, Class Unloading, taking 0.0025840s;
   • In addition to the previous events, the most critical outcome of this phase is to draw the final look of the entire heap in the current concurrent cycle, where the remaining SATB buffers are processed and all surviving objects are marked;

5. The cleanup phase also stops the World

   • The last surviving object is calculated: the object allocated after the initial-mark stage is marked; Marks the partition that has at least one living object;
   • In preparation for the next concurrent marking phase, previous and next bitmaps are cleaned;
   • Old age partitions and large object partitions with no surviving objects are freed and cleaned up;
   • Rsets that handle partitions without any living objects;
   • All old age partitions will be sorted according to their survival rate (the proportion of living objects to the size of the entire partition), to prepare for the subsequent CSet selection process.

6. Concurrent cleanup phase

   • GC concurrent-cleanup-start: starts the concurrent cleanup phase. Complete the remaining cleaning work in Step 5. Add the fully cleaned partition to the secondary free list and wait until it finally returns to the overall free list.
   • GC concurrent-cleanups-end: indicates that the concurrent cleanup phase ends, which takes 0.0012954 seconds

Mixed collection

After the concurrent collection phase is over, you should see the mixed collection phase log, as shown below. Most of the log is the same as the previous generation collection discussed, except for part 1: GC Pause (G1 Evacuation Pause)(mixed),0.0129474s, this line indicates that this is a mixed garbage collection cycle; The CSet in the mixed garbage collection process includes not only Cenozoic partitions, but also older partitions — that is, those marked by the concurrent marking phase.

Full GC

If there is not enough heap memory space to allocate new objects, or if Metasapce space usage reaches a set threshold, then Full GC will trigger — something you should try to avoid when using G1, because Full GC is single-threaded and stops The World at a high cost. The Full GC log is shown below, where you can see three types of information

1. A common cause of Full GC is Allocation Failure and Metadata GC Threshold.
2. The frequency of Full GC, one every few days is acceptable, but one every hour is unacceptable;
3. Full GC takes 150ms in this picture (PS: In my experience, it would take much more if a Full GC were to happen)

Basic configuration parameters, here I want to introduce two: – XX: XX: + PrintGCApplicationStoppedTime and – + PrintGCApplicationConcurrentTime, these two parameters can also provide useful information for you, as shown in the figure below:

1. It records the total time the application thread was suspended at the safe point (that is, the total time STW).
2. It records the total time it takes to get all the application threads to the safe point
3. Logs how long the application thread runs between two safety points

conclusion

This article only translated the first part of the original text, the basic parameter part. I will complete the advanced parameter and Debug parameter parts of the original text in one or two articles next. ——

This issue focuses on topics such as backend technology, JVM troubleshooting and optimization, Java interview questions, personal growth and self-management, providing readers with front-line developer work and growth experience, looking forward to your harvest here.