GC log

• Overview
• How to generate?
• UC JVM opstions
• Analysis
  • Minor GC
  • Major / Full GC
    • Phase 1: Initial Mark[Stop the World]
    • Phase 2: Concurrent Mark
    • Phase 3: Concurrent Preclean
    • Phase 4: Concurrent Abortable Preclean
    • Phase 5: Final Remark[Stop the World]
    • Phase 6: Concurrent Sweep
    • Phase 7: Concurrent Reset
  • -XX:+PrintHeapAtGC

Overview

We can get into k8s pod and step into the gc.log place. We input less gc.log，then we can see the information above。

How to generate?

First of all, we want to understand gc log, we need to generate it.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<file-path>

Add the above parameters to JVM，there will be gc log in <file-path>.

 

-XX:+PrintGCDetails  would print the details of how much memory is reclaimed in each generation.

-XX:+PrintGCDateStamps would print the absolute time stamp in the log statement.

Our JVM opstions

Now we start with analysis with our JVM opstions:

JAVA_MEM_OPTS="-XX:InitialRAMPercentage=60.0 -XX:MaxRAMPercentage=60.0 -XX:MinRAMPercentage=60.0 -XX:NewRatio=2 -XshowSettings:vm -XX:+PrintFlagsFinal -XX:+ExplicitGCInvokesConcurrent -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m -XX:+PrintHeapAtGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -verbose:gc -Xloggc:$LOG_DIR/gc.log -Djava.net.preferIPv4Stack=true -Dcat.log.path=$LOG_DIR"

Terminal output

CommandLine flags: -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:CompressedClassSpaceSize=260046848 -XX:+ExplicitGCInvokesConcurrent -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:InitialHeapSize=644245094 -XX:InitialRAMPercentage=60.000000 -XX:LargePageSizeInBytes=134217728 -XX:MaxHeapSize=644245094 -XX:MaxMetaspaceSize=268435456 -XX:MaxRAMPercentage=60.000000 -XX:MaxTenuringThreshold=6 -XX:MetaspaceSize=268435456 -XX:MinRAMPercentage=60.000000 -XX:NewRatio=2 -XX:OldPLABSize=16 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastAccessorMethods -XX:+UseParNewGC

Type		Options	Function	UC value
Standard Options supported by all implementations of the JVM		-verbose:gc	Displays information about each garbage collection(GC) event.	-verbose:gc
Non-Standard Options specific to the Java HotSpot Virtual Machine	general purpose	-XshowSettings:category	Show settings and continues. Possible category arguments: all: Shows all categories of settings. This is the default value locale: Shows setting related to locale. properties: Show settings related to system properties. vm: Shows the settings of the JVM.	-XshowSettings:vm
		-Xloggc:filename	Sets the file to which verbose GC events information should be directed for logging.	-Xloggc:$LOG_DIR/gc.log
	advanced runtime options control the  runtime behavior of the JVM Hotspot VM	-XX:CMSInitiatingOccupancyFraction=percent	set the percentage of the old generation occupancy（0 to 100）at which to start a CMS collection cycle. The default value is set to -1. Any negative value (including the default) implies that -XX:CMSTriggerRatio is used to define the value of the initiating occupancy fraction.	-XX:CMSInitiatingOccupancyFraction=70
		-XX:+ExplicitGCInvokesConcurrent	Enables invoking of concurrent GC by using the System.gc() request. This option is disabled by default and can be enabled only together with the -XX:+UseConcMarkSweepGC option.	-XX:+ExplicitGCInvokesConcurrent
		-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses	Enables invoking of concurrent GC by using the System.gc() request and unloading of classes during the concurrent GC cycle. This option is disabled by default and can be enabled only together with the -XX:+UseConcMarkSweepGC option.	-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
		-XX:+PrintGCDetails	Enables printing of detailed messages at every GC. By default, this option is disabled.	-XX:+PrintGCDetails
		-XX:+PrintGCTimeStamps	Enables printing of time stamps at every GC. By default, this option is disabled.	-XX:+PrintGCTimeStamps
		-XX:+UseCMSInitiatingOccupancyOnly	Enables the use of the occupancy value as the only criterion for initiating the CMS collector. By default, this option is disabled and other criteria may be used.	-XX:+UseCMSInitiatingOccupancyOnly
		-XX:+UseConcMarkSweepGC	Enable the use of the CMS garbage collector for the old generation.  Oracle recommends that you use the CMS garbage collector when application latency requirements cannot be met by the throughput (-XX:+UseParallelGC) garbage collector. The G1 garbage collector (-XX:+UseG1GC) is another alternative. By default, this option is disabled and the collector is chosen automatically based on the configuration of the machine and type of the JVM. When this option is enabled, the -XX:+UseParNewGC option is automatically set and you should not disable it, because the following combination of options has been deprecated in JDK 8: -XX:+UseConcMarkSweepGC -XX:-UseParNewGC.	-XX:+UseConcMarkSweepGC
		-XX:InitialRAMPercentage=percent	Sets the initial amount of memory that the JVM will use for the Java heap before applying ergonomics heuristics as a percentage of the maximum amount determined as described in the -XX:MaxRAM option. The default value is 1.5625 percent.	-XX:InitialRAMPercentage=60.0
		-XX:MaxRAMPercentage=percent	Sets the maximum amount of memory that the JVM may use for the Java heap before applying ergonomics heuristics as a percentage of the maximum amount determined as described in the -XX:MaxRAM option. The default value is 25 percent.	-XX:MaxRAMPercentage=60.0
		-XX:MinRAMPercentage=percent	Sets the maximum amount of memory that the JVM may use for the Java heap before applying ergonomics heuristics as a percentage of the maximum amount determined as described in the -XX:MaxRAM option for small heaps. A small heap is a heap of approximately 125 MB. The default value is 50 percent.	-XX:MinRAMPercentage=60.0
		-XX:NewRatio=ratio	Sets the ratio between young and old generation sizes. By default, this option is set to 2.  -XX:NewRatio=2 means the old generation occupies 2 times space than young generation. Generally, we don't allow ratio is less than 1, which means old must be larger than young.	-XX:NewRatio=2
		-XX:MetaspaceSize=size	Sets the size of the allocated class metadata space that will trigger a garbage collection the first time it is exceeded. This threshold for a garbage collection is increased or decreased depending on the amount of metadata used. The default size depends on the platform.	-XX:MetaspaceSize=256m
		-XX:MaxMetaspaceSize=size	Sets the maximum amount of native memory that can be allocated for class metadata. By default, the size is not limited. The amount of metadata for an application depends on the application itself, other running applications, and the amount of memory available on the system.	-XX:MaxMetaspaceSize=256m
		-XX:LargePageSizeInBytes=size	On Solaris, sets the maximum size (in bytes) for large pages used for Java heap. The size argument must be a power of 2 (2, 4, 8, 16, ...). Append the letter k or K to indicate kilobytes, m or M to indicate megabytes, g or G to indicate gigabytes. By default, the size is set to 0, meaning that the JVM chooses the size for large pages automatically.	-XX:LargePageSizeInBytes=128m
		-XX:+CMSParallelRemarkEnabled	The option CMSParallelRemarkEnabled means the remarking is done in parallel to program execution – which is what you want if your server has many cores (and most servers do).	-XX:+CMSParallelRemarkEnabled
		-XX:[+|-]PrintFlagsFinal	When enabled, this option outputs the values of a subset of configuration parameters in a format compatible with that produced by HotSpot. The parameters currently output are those expected by various software projects and packages.	-XX:+PrintFlagsFinal
		-XX:+PrintHeapAtGC	which prints two snapshots of the heap memory for each GC, one before the GC and another after the GC.	-XX:+PrintHeapAtGC
		-XX:+UseFastAccessorMethods	Use optimized versions of Get<Primitive>Field.	-XX:+UseFastAccessorMethods

We can use command  jinfo -flag  [certain  parameter] pid  to show  certain pid certain parameter's value.

 

use jinfo -flag CMSInitiatingOccupancyFraction 1  we can see that our config is active that CMSInitiatingOccupancyFraction is set to 70. 

Analysis

Now we cut to the chase to analyze what's in the gc.log.(noted: here without three options: -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m -XX:+PrintHeapAtGC)

 

recap this picture.

The first row prints the current java version and vm;

The second row prints the memory info of the operating system;

The third row prints the option parameters info of current running java application.

From the forth row, here comes to our gc logs.

Minor GC

1.663: [GC (Allocation Failure) 1.663: [ParNew: 168256K->8909K(189248K), 0.0873393 secs] 168256K->8909K(609792K), 0.0874175 secs] [Times: user=0.07 sys=0.01, real=0.09 secs]

 

1. 1.663 is the gc starting time relative to the time jvm was started.
2. GC  indicates that it's a minor gc, if there is FULL before GC, it means it's a full gc. It shows the type of garbage collection.
3. (Allocation Failure) indicates that there's no enough space to allocate to store new data in young generation which led to garbage collection.
4. 1.663 is the gc time since jvm was started.
5. ParNew indicates that this garbage collection happened in Young Generation and ParNew garbage collector was used to do that. The ParNew collector is essentially a multithreaded parallel version of the Serial collector; it uses mark-copy algorithms and leads to "Stop the World".
6. 168256K→8909K(189248K):the three parameters respectively represent this area(here is Young generation) used memory space before gc, this area used memory space after gc, total memory of this memory area.
7. 0.0873393 secs: the cost time of  this memory area garbage collection.
8. 168256K→8909K(609792K): the three parameters respectively represent heap used memory before gc, heap used memory after gc, total heap memory.
9. 0.0874175 secs: the cost time of  this memory area garbage collection.(the time ParNew collector mark and copy objects including the time communication with old generation,  the time objects promoting to old generation and the time of cleaning objects after the period of garbage collection).
10. Times: user=0.07 sys=0.01, real=0.09 secs: 
    • user – Total CPU time that was consumed by Garbage Collector threads during this collection
    • sys – Time spent in OS calls or waiting for system event
    • real – Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by the Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount.

So, as a summary, we can know the young generation has decreased 168256K-8909K= 159347K in this garbage collection, heap area has decreased 168256K-8909K= 159347K which equals to young generation decrease.  This means there is no objects moving to old generation, they are all life-short objects. And the whole progress the old generation share  0 space.

Major / Full GC

Phase 1: Initial Mark[Stop the World]

Two objectives:

1. Mark all GC roots in the old generation.
2. Mark the objects which are referenced by live objects in young generation.

 

1. 16.572 relative to the time JVM started
2. CMS Initial Mark: marking stage, starting marking all GC roots and directly referenced objects.
3. 31369K: current old generation used situation
4. 420544K:  old generation available capacity 
5. 44418K:  the currently whole heap used situation
6. 609792K: available heap capacity
7. 0.0116893 secs: time-cost of major GC
8. Times: user=0.07 sys=0.01, real=0.09 secs: same as above.

Phase 2: Concurrent Mark

This phase will traverse all the old-generation objects and mark the live objects. starting with GC roots found in the phase "initial mark".

The character of concurrent mark is the gc-thread is running with application-thread.

Not all the live objects in the old generation will be marked, since application-thread will change the reference of some objects.

 (You can see one referencing arrow has been removed from current object)

 

1. CMS-concurrent-mark: concurrently collecting phase, which will traverse old-generation objects and mark live objects.
2. 0.169/0.169 secs: Duration of the phase, showing elapsed time and wall clock time correspondingly.

Phase 3: Concurrent Preclean

This phase is a concurrent phase, running in parallel with the application threads, not stoping them.

JVM marks the area of the heap(callsed "Card") that contains the mutated object as "dirty".

 In the pre-cleaning phase, these dirty objects are accounted for, and the objects reachable from them are also marked. The card are cleaned when this is done.

 

1. CMSconcurrent-preclean:  accounting for references being changed during previous marking phase.
2. 0.002/0.002 secs: duration of the phase

Phase 4: Concurrent Abortable Preclean

This concurrent phase will not stop the application thread.

This one attempts to takes as much work off the shoulders of the stop-the-world Final Remark as possible. The exact duration of this phase depends on a number of factors, since it iterates doing the same thing until one of the abortion conditions(such as the number of iterations, amount of useful work done, elapsed wall clock time, etc) is met.

 

1. CMS-concurrent-abortable-preclean
2. 0.556/0.626 secs: duration of the phase, we can see the user time reported is smaller than clock time, meaning that some work was done in parallel, so the clock time is less than cpu time.By default, this phase may last for up to 5 seconds.

This phase may significantly impact the duration of the upcoming stop-the-world pause, and has quite a lot of non-trivial configuration options and fail modes.

Phase 5: Final Remark[Stop the World]

This is the second and last stop-the-world phase during CMS.

The goal of this stop-the-world phase is to finalize marking all live objects in the old generation. Since the previous preclean phase were concurrent, they may have been unable to keep up with application's mutating speed. A stop-the world pause is required to finish the ordeal.

Usually CMS tries to run final remark phase when young generation is as empty as possible in order to eliminate the possibility of several stop-the-world happening back-to-back.

 

1. CMS Final Remark: marking all live objects in old generation, including the references that were created or modified during previous concurrent marking phase.
2. YG occupancy: 113729K(189248K): current occupancy and capacity of young generation.
3. Rescan(parallel), 0.1131085 secs: complete marking all live objects while application is stopped. In this case, the rescan was done in parallel and took 0.1131085 seconds.
4. weak refs processing, 0.0000748 secs: First of the sub-phases that is processing weak references along with the duration and timestamp of the phase.
5. class unloading, 0.0101342 secs: Next sub-phase that is unloading the unused classes, with the duration of the phase.
6. scrub symbol table, 0.0068621 secs: Next sub-phase that is cleaning up symbol table which hold class-level metadata, with duration of the phase.
7. scrub string table, 0.0006762 secs: Last sub-phase that is cleaning up string table which hold internalized string, with duration of the phase.
8. CMS-remark: 31369K(420544K): occupancy and capacity of old generation.
9. 145098K(609792K), 0.1309537 secs: usage and the capacity of the total heap after the phase, with duration of the phase.
10. Times: user=0.08 sys=0.00, real=0.14 secs: Duration of the pause, measured in user, system and real time categories.

After the five marking phases, all live objects in old generation are marked and now garbage collector is going to reclaim all unused objects by sweeping the old generation.

Phase 6: Concurrent Sweep

Performed concurrently with the application, without the need for the stop-the-world pauses.

The purpose of this phase is to remove unused objects and to reclaim the space occupied by them for future use.

 

 

1. CMS-concurrent-sweep:  concurrently sweep the unmarked thus unused objects to reclaim space.
2. 0.037/0.037 secs: duration of the phase.

Phase 7: Concurrent Reset

Concurrently executed phase, resetting inner data structure of the CMS algorithm and preparing the for the next cycle.

 

1. CMS-concurrent-reset: resetting the inner data structure of CMS algorithm and preparing them for next cycle.
2. 0.001/0.001 secs: duration of the phase.

All in all, the CMS garbage collector does a great job at reducing the pause duration by offloading a great deal of the work to concurrent threads that do not require the application  to stop.

However, it also has drawbacks, the most notable of them being the old generation fragmentation and the lack of predictability in pause durations in some cases, especially on large heaps.

-XX:+PrintHeapAtGC

 Here, let's take a look at the output of -XX:+PrintHeapAtGC.

This command enabled will prints two snapshots of the heap memory for each GC, one before the GC and another after the GC.

 

we can see the one snapshot of heap memory before the GC and another after the GC.

Before gc: par new generation used 1342464K = eden used. old generation is not used at the beginning. 

Since eden space is 100% used, there is no space which can be allocated to new objects, GC is invoked.

After gc: some objects are copied to survivor, old generation is still  not used. Par new generation used space decrease from 134246K to 36219K, while 134246K was in eden space before, after 36219K is in from survivor. 

which means 134246k-36219K=1306245K objects are life-short and need to be reclaimed.

---

Reference

1.GC Algorithms: Implementations | Plumbr – User Experience & Application Performance Monitoring 

2.GC之详解CMS收集过程和日志分析 - 凌渡冰 - 博客园

3. java