3. Garbage First Garbage Collector Performance Tuning

Performance engineering deals with the nonfunctional performance requirements of a system or its software and ensures that the design requirements are met in the product implementation. Thus it goes hand-in-hand with systems or software engineering.

In this chapter, we will discuss performance tuning in detail, concentrating on the newest garbage collector in Java HotSpot VM: Garbage First, or G1. We will skip young generation tuning advice already provided in Java™ Performance [1], particularly Chapter 7, “Tuning the JVM, Step by Step.” Readers are encouraged to read that chapter and also the previous chapters in this supplemental book.

Let’s look at an excerpt from a G1 GC output log generated while running DaCapo with the HotSpot VM command-line option -XX:+PrintGCDetails. Here is the command-line and “Java version” output:

Click here to view code image

This is the GC log snippet (jdk8u45_h2.log):

Click here to view code image

The snippet shows one G1 GC young collection pause, identified in the first line by (G1 Evacuation Pause) and (young). The line’s timestamp is 108.815, and total pause time is 0.0543862 seconds:

Click here to view code image

Click here to view code image

The following lines show the major parallel work carried out by the eight worker threads:

Click here to view code image

GC Worker Start and GC Worker End tag the starting and ending timestamps respectively of the parallel phase. The Min timestamp for GC Worker Start is the time at which the first worker thread started; similarly, the Max timestamp for GC Worker End is the time at which the last worker thread completed all its tasks. The lines also contain Avg and Diff values in milliseconds. The things to look out for in those lines are:

How far away the Diff value is from 0, 0 being the ideal.

Any major variance in Max, Min, or Avg. This indicates that the worker threads could not start or finish their parallel work around the same time. That could mean that some sort of queue-handling issue exists that requires further analysis by looking at the parallel work done during the parallel phase.

Click here to view code image

Here again, we look for Diff >> 0 and major variance in Max, Min, or Avg.

Another thing to watch out for is whether a worker thread is caught up in dealing with a single root. We have seen issues where the system dictionary, which is treated as a single root, ends up holding up a worker thread when there is a large number of loaded classes. When a worker thread is late for “termination” (explained later in this section), it is also considered held up.

As explained in Chapter 2, “Garbage First Garbage Collection in Depth,” G1 GC uses remembered sets (RSets) to help maintain and track references into G1 GC regions that “own” those RSets. The concurrent refinement threads, also discussed in Chapter 2, are tasked with scanning the update log buffers and updating RSets for the regions with dirty cards. In order to supplement the work carried out by the concurrent refinement threads, any remainder buffers that were logged but not yet processed by the refinement threads are handled during the parallel phase of the collection pause and are processed by the worker threads. These buffers are what are referred to as Processed Buffers in the log snippet.

In order to limit the time spent updating RSets, G1 sets a target time as a percentage of the pause time goal (-XX:MaxGCPauseMillis). The target time defaults to 10 percent of the pause time goal. Any evacuation pause should spend most of its time copying live objects, and 10 percent of the pause time goal is considered a reasonable amount of time to spend updating RSets. If after looking at the logs you realize that spending 10 percent of your pause time goal in updating RSets is undesirable, you can change the percentage by updating the -XX:G1RSetUpdatingPauseTimePercent command-line option to reflect your desired value. It is important to remember, however, that if the number of updated log buffers does not change, any decrease in RSet update time during the collection pause will result in fewer buffers being processed during that pause. This will push the log buffer update work off onto the concurrent refinement threads and will result in increased concurrent work and sharing of resources with the Java application mutator threads. Also, worst case, if the concurrent refinement threads cannot keep up with the log buffer update rate, the Java application mutators must step in and help with the processing—a scenario best avoided!

Before collecting regions in the current CSet, the RSets for the regions in the CSet must be scanned for references into the CSet regions. As discussed in Chapter 2, a popular object in a region or a popular region itself can lead to its RSet being coarsened from a sparse PRT (per-region table) to a fine-grained PRT or even a coarsened bitmap, and thus scanning such an RSet will require more time. In such a scenario, you will see an increase in the Scan RS time shown here since the scan times depend on the coarseness gradient of the RSet data structures:

Click here to view code image

Another parallel task related to RSets is code root scanning, during which the code root set is scanned to find references into the current CSet:

Click here to view code image

In earlier versions of HotSpot, the entire code cache was treated as a single root and was claimed and processed by a single worker thread. A large and full or nearly full code cache would thus hold up that worker thread and lead to an increase in the total pause time. With the introduction of code root scanning as a separate parallel activity, the work of scanning the nmethods is reduced to just scanning the RSets for references from the compiled code. Hence for a particular region in the CSet, only if the RSet for that region has strong code roots is the corresponding nmethod scanned.

Here is a GC log snippet with the RSets summarized on every GC pause:

Click here to view code image

Click here to view code image

The main things to look out for in this snippet are as follows:

Click here to view code image

The log output is printed for both before and after the GC pause. The Processed cards tag summarizes the work done by the concurrent refinement threads and sometimes, though very rarely, the Java application mutator threads. In this case, 96 completed buffers had 23,270 processed cards, and all (100 percent) of the work was done by the concurrent RSet refinement threads. There were no RSet coarsenings as indicated by Did 0 coarsenings.

Other parts of the log output describe concurrent RSet times and current RSet statistics, including their sizes and occupied cards per region type (young, free, humongous, or old). You can use the log to figure out how the code root sets are referencing the RSets for each region type as well as the total number of references per region type.

Click here to view code image

Click here to view code image

If any (or all) worker threads are getting caught up somewhere, it will show up in long termination times and may indicate a work-stealing or load-balancing issue.

Click here to view code image

Click here to view code image

Click here to view code image

Reference processing and enqueuing are for soft, weak, phantom, final, and JNI references. We discuss this and more in the section titled “Reference Processing Tuning.”

The act of reference enqueuing may require updating the RSets. Hence, the updates need to be logged and their associated cards need to be marked as dirty. The time spent redirtying the cards is shown as the Redirty Cards time (0.2 ms in the preceding example).

Humongous Reclaim is new in JDK 8u40. If a humongous object is found to be unreachable by looking at all references from the root set or young generation regions and by making sure that there are no references to the humongous object in the RSet, that object can be reclaimed during the evacuation pause. (See Chapter 2 for detailed descriptions of humongous regions and humongous objects.)

The remainder of the Other time is spent in fixing JNI handles and similar work. The collective time in Other should be very small, and any time hog should have a reasonable explanation. As an example, you could see higher times in Free CSet if your CSet per pause is very large. Similarly, Ref Proc and Ref Enq could show higher times depending on how many references are used in your application. Similar reasoning can be applied to Humongous Reclaim times, if you have many short-lived humongous objects.

G1 GC has great tuning potential. There are initial and default values that help G1 GC’s heuristics, and in order to be able to tune G1 GC, one needs to understand these defaults and their effect on the heuristics. Options such as -XX:MaxGCPauseMillis (pause time goal; defaults to 200 ms), -XX:G1NewSizePercent (initial young generation size expressed as a percentage of the total heap; defaults to 5 percent), and -XX:G1MaxNewSizePercent (maximum young generation growth limit expressed as a percentage of the total heap; defaults to 60 percent) help grow or shrink the young generation based on the initial and upper bounds, the pause time goal, and the weighted average of previous copy times. If there is a good understanding of the workload and if there is a perceived benefit from circumventing the adaptive resizing (for example, if you see that the predicted time varies drastically from the actual time observed), you can adjust the defaults. The side effect is that you are forgoing adaptive resizing for more predictable limits. Another thing to keep in mind is that the new limits are applicable only to the one application that you are tuning and will not carry forward to any other/different applications that may have similar pause time requirements since most applications exhibit different behaviors based on their allocation rates, promotion rates, steady and transient live data sets, object sizes, and life spans.

Let’s look at some examples. These are once again run using JDK 8u45 with different values for -XX:MaxGCPauseMillis (as can be seen in the time noted as the target pause time). The benchmark suite was DaCapo, and -XX:+PrintAdaptiveSizePolicy was enabled at the JVM command line.

Click here to view code image

In the above example, the pause time goal was left at its default value of 200ms, and it was observed that even though the prediction logic predicted the pause time to be 222.44ms, the actual pause time was only 112.63 ms. In this case, we could have easily added more young regions to the CSet.

Click here to view code image

The second example above showcases a similar scenario to the one shown before, only here the pause time target was changed to 50 ms (no adjustments were made to the young generation). Once again, the prediction logic was off and it predicted a pause time of 75.36 ms, whereas the actual pause time was 21.86 ms.

After adjusting the young generation (as can be seen in the number of eden and survivor regions added to the CSet in the third example, below), we could get the pause times to be in the 50 ms range as shown here:

Click here to view code image

Here, even though the prediction logic is still way off, our pause time (50.75 ms) is in the desired range (50 ms).

The concurrent marking cycle starts with an initial marking pause which happens at the same time as (aka, is “piggybacked onto”) a young collection pause. This pause marks the beginning of the collection cycle and is followed by other concurrent and parallel tasks for root region scanning, concurrent marking and liveness accounting, final mark, and cleanup. Figure 3.1 shows all the pauses in a concurrent marking cycle: initial mark, remark, and cleanup. To learn more about the concurrent marking cycle please refer to Chapter 2.

Click here to view code image

The concurrent marking tasks can take a long time if the application’s live object graph is large and may often be interrupted by young collection pauses. The concurrent marking cycle must be complete before a mixed collection pause can start and is immediately followed by a young collection that calculates the thresholds required to trigger a mixed collection on the next pause, as shown in Figure 3.1. The figure shows an initial-mark pause (which, as mentioned earlier, piggybacks on a young collection). There could be more than one young collection when the concurrent phase is under way (only one pause is shown in the figure). The final mark (also known as remark) completes the marking, and a small cleanup pause helps with the cleanup activities as described in Chapter 2. There is a young generation evacuation pause right after the cleanup pause which helps prepare for the mixed collection cycle. The four pauses after this young collection pause are the mixed collection evacuation pauses that successfully collect all the garbage out of the target CSet regions.

If any of the concurrent marking tasks and hence the entire cycle take too long to complete, a mixed collection pause is delayed, which could eventually lead to an evacuation failure. An evacuation failure will show up as a to-space exhausted message on the GC log, and the total time attributed to the failure will be shown in the Other section of the pause. Here is an example log snippet:

Click here to view code image

When you see such messages in your log, you can try the following to avoid the problem:

It is imperative to set the marking threshold to fit your application’s static plus transient live data needs. If you set the marking threshold too high, you risk running into evacuation failures. If you set the marking threshold too low, you may prematurely trigger concurrent cycles and may reclaim close to no space during your mixed collections. It is generally better to err on the side of starting the marking cycle too early rather than too late, since the negative consequences of an evacuation failure tend to be greater than those of the marking cycle running too frequently.

If you think that the marking threshold is correct, but the concurrent cycle is still taking too long and your mixed collections end up “losing the race” to reclaim regions and triggering evacuation failures, try increasing your total concurrent thread count. -XX:ConcGCThreads defaults to one-fourth of -XX:ParallelGCThreads. You can either increase the concurrent thread count directly or increase the parallel GC thread count, which effectively increases the concurrent thread count.

The -XX:+PrintAdaptiveSizePolicy option dumps details of G1’s ergonomics heuristic decisions. An example follows.

First the command line:

Click here to view code image

And the log snippet:

Click here to view code image

The first line tells us the evacuation pause type, in this case a mixed collection, and the predicted times for activities such as CSet selection and adding young and old regions to the CSet.

On the fifth timestamp, tagged Mixed GCs, you can see G1 decide to continue with mixed collections since there are candidate regions available and reclaimable bytes are still higher than the default 5 percent threshold.

This example highlights two tunables: the number of old regions to be added to the CSet as can be seen here:

Click here to view code image

and the reclaimable percentage threshold:

Click here to view code image

Let’s talk more about these and other tunables next.

Click here to view code image

The last line of this example shows that mixed GCs will be continued since there is enough garbage to be reclaimed (10.24 percent). Here the reclaimable percentage threshold is kept at its default value of 5 percent.

If mixed collections are becoming exponentially expensive as can be seen in Figure 3.2, increasing this threshold will help. Remember, however, that the increase will leave more regions fragmented and occupied. This means that the old generation will retain more (transient) live data, which must be accounted for by adjusting your marking threshold accordingly.

The minimum threshold for the number of old regions to be included in the CSet per mixed collection pause within a mixed collection cycle is specified by -XX:G1MixedGCCountTarget and defaults to 8. As briefly discussed in Chapter 2, the minimum number of old regions per mixed collection pause is

Minimum old CSet size per mixed collection pause = Total number of candidate old regions identified for mixed collection cycle/G1MixedGCCountTarget

This formula determines the minimum number of old regions per CSet for each mixed collection to be x such as to facilitate y back-to-back mixed collections that will collect all candidate old regions. The set of back-to-back mixed collections carried out after a completed concurrent marking cycle constitutes a mixed collection cycle. Let’s look at line 4 of the preceding example:

Click here to view code image

Line 4 tells us that only 24 regions were added to the CSet, since the minimum number of old regions to be added per CSet was not met. The previous (young) collection pause tells us that there are 189 candidate old regions available for reclamation, hence G1 GC should start a mixed collection cycle:

Click here to view code image

So, dividing 189 by the default value of G1MixedGCCountTarget (8) = Ceiling (189/8) = 24. And that is how we get to the minimum number of 24 regions.

Just as there is a minimum threshold for old regions to be added to the CSet, there is a maximum as well. The value for the maximum threshold for the old regions to be added to the CSet is specified by -XX:G1OldCSetRegionThresholdPercent, which defaults to 10 percent of the total Java heap size. Once again, let’s look at an example:

Click here to view code image

Lines 3 and 5 show that even though there were more candidate old regions available for collection, the total number of old regions in the current CSet was capped at 103 regions. As mentioned in the preceding description, the 103 region count comes from the total heap size of 1G and the 10 percent default value for G1OldCSetRegionThresholdPercent, which rounds up to 103.

Now that we know how to specify the minimum and maximum number of regions per CSet per mixed collection, we can modify the thresholds to suit our pause time goal and at the same time maintain the desired amount of transient live data in the old generation.

The -XX:G1MixedGCLiveThresholdPercent option, which defaults to 85 percent (JDK 8u45), is the maximum percentage of live data within a region that will allow it to be included in a CSet. Per-region live data percentages are computed during the concurrent marking phase. An old region deemed to be too expensive to evacuate—that is, whose live data percentage is above the liveness threshold—is not included as a CSet candidate region. This option directly controls fragmentation per region, so be careful.

Heap size. Make sure that you can accommodate all the static and transient live data and your short- and medium-lived application data in your Java heap. Apart from the accommodation of live data, additional Java heap space, or headroom, should be available in order for GC to operate efficiently. The more the available headroom, the higher the possible throughput and/or the lower the possible latency.

Avoid over-specifying your JVM command-line options! Let the defaults work for you. Get a baseline with just your initial and maximum heap settings and a desired pause time goal. If you already know that the default marking threshold is not helping, add your tuned marking threshold on the command line for the baseline run. So, your base command would look something like this:

Click here to view code image

-Xms2g -Xmx4g -XX:MaxGCPauseMillis=100

or

Click here to view code image

-Xms2g -Xmx4g -XX:MaxGCPauseMillis=100 -
XX:InitiatingHeapOccupancyPercent=55

If your application has long-lived humongous objects, make sure that your marking threshold is set low enough to accommodate them. Also, make sure that the long-lived objects that you deem “humongous” are treated as such by G1. You can ensure this by setting -XX:G1HeapRegionSize to a value that guarantees that objects greater than or equal to 50 percent of the region size are treated as humongous. As mentioned in Chapter 2, the default value is calculated based on your initial and maximum heap sizes and can range from 1 to 32MB.

Here is a log snippet using -XX:+PrintAdaptiveSizePolicy:

Click here to view code image

A concurrent cycle is being requested since the heap occupancy crossed the marking threshold due to a humongous allocation request. The request was for 2,097,168 bytes, which is far larger than the 1MB G1 heap region size default set by G1 at JVM start-up time.

There are times when evacuation failures are caused by not having enough space in the survivor regions for newly promoted objects. When you observe this happening, try increasing -XX:G1ReservePercent. The reserve percent creates a false ceiling for the reserved space so as to accommodate any variation in promotion patterns. The default value is 10 percent of the total Java heap and is limited by G1 to 50 percent of the total Java heap since more would amount to a very large amount of wasted reserve space.

In this section, you will learn how to identify if the time required to perform reference processing during a G1 garbage collection pause is an issue for your application and how to tune G1 to reduce this overhead, along with tips for isolating which reference object type is inducing the most overhead. Depending on the application and its pause time requirements, refactoring the application’s source code may be required to reduce reference processing overhead.

Click here to view code image

Ref Proc is the time spent processing reference objects, and Ref Enq is the time spent enqueuing reference objects. As the example suggests, the time spent in Ref Enq is rarely as long as the time spent in Ref Proc. In fact, we have yet to see an application that consistently has higher Ref Enq times. If it happens, it means that the amount of effort required to process a reference is very small relative to its enqueuing time, which is unlikely for most reference object types.

G1 also reports reference processing activity during the remark phase during G1’s concurrent cycle. Using -XX:+PrintGCDetails, the log output from remark will include reference processing time:

Click here to view code image

-XX:+PrintReferenceGC reports details for each reference object type at each collection and is very useful for isolating a specific reference object type that the collector is spending the most time processing.

Click here to view code image

Note that G1 is the only HotSpot GC that reports reference processing times with -XX:+PrintGCDetails. However, all HotSpot GCs will report per-reference-object-type information using -XX:+PrintReferenceGC.

As a general guideline, Ref Proc times in PrintGCDetails output that are more than 10 percent of the total GC pause time for a G1 young or mixed GC are cause to tune the garbage collector’s reference processing. For G1 remark events it is common to see a larger percentage of time spent in reference processing since the remark phase of the concurrent cycle is when the bulk of reference objects discovered during an old generation collection cycle are processed. If the elapsed time for the G1 remark pause exceeds your target pause time and a majority of that time is spent in reference processing, tune as described in the next section.

If reference processing time remains larger than 10 percent of young or mixed GC pause times after adding -XX:+ParallelRefProcEnabled, or G1’s remark phase is spending too much time in reference processing, the next step is to determine which reference object type or set of reference object types G1 is spending most of its time processing. -XX:+PrintReferenceGC will report statistics on each reference object type at each GC:

Click here to view code image

A large number of a particular reference object type indicates that the application is heavily using it. Suppose you observe the following:

Click here to view code image

In addition, further suppose you regularly observe a similar pattern of a high number of weak references across other GCs. You can use this information to refactor your application in order to reduce the use of the identified reference object type, or to reduce the reclamation time of that reference object type. In the preceding example, the number of processed weak references is very high relative to the other reference object types, and the amount of time to process them also dominates reference processing time. Corrective actions include the following:

1. Verify that -XX:+ParallelRefProcEnabled is enabled. If it is not, enable it and observe whether it reduces pause time enough to reach your pause time goal.

2. If -XX:+ParallelRefProcEnabled is enabled, tell the application developers that you are observing a very high weak reference reclamation rate and ask that they consider refactoring the application to reduce the number of weak references being used.

One reference object type to watch for and be careful of using is the soft reference. If PrintReferenceGC log output suggests that a large number of soft references are being processed, you may also be observing frequent old generation collection cycles, which consist of concurrent cycles followed by a sequence of mixed GCs. If you see a large number of soft references being processed and GC events are occurring too frequently, or heap occupancy consistently stays near the maximum heap size, tune the aggressiveness with which soft references are reclaimed using XX:SoftRefLRUPolicyMSPerMB. It defaults to a value of 1000, and its units are milliseconds.

The default setting of -XX:SoftRefLRUPolicyMSPerMB=1000 means that a soft reference will be cleared and made eligible for reclamation if the time it was last accessed is greater than 1000ms times the amount of free space in the Java heap, measured in megabytes. To illustrate with an example, suppose -XX:SoftLRUPolicyMSPerMS=1000, and the amount of free space is 1GB, that is, 1024MB. Any soft reference that has not been accessed since 1024 × 1000 = 1,024,000ms, or 1024 seconds, or slightly over 17 minutes ago, is eligible to be cleared and reclaimed by the HotSpot garbage collector.

The effect of setting a lower value for -XX:SoftRefLRUPolicyMSPerMB is to provoke more aggressive clearing and reclamation of soft references, which leads to lower heap occupancy after GC events, or in other words, less live data. Conversely, setting -XX:SoftRefLRUPolicyMSPerMB higher causes less aggressive soft reference clearing and reclamation, which leads to more live data and higher heap occupancy. Tuning -XX:SoftRefLRUPolicyMSPerMB may not actually lead to lower reference processing times and in fact may increase them.

The primary reason to tune -XX:SoftRefLRUPolicyMSPerMB is to reduce the frequency of old generation collection events by reducing the amount of live data in the heap. We recommend against the use of soft references as a means for implementing memory-sensitive object caches in Java applications because doing so will increase the amount of live data and result in additional GC overheads. See the sidebar “Using Soft References” for more detail.

[2] Nirmar S. Arora, Robert D. Blumofe, and C. Greg Plaxton. “Thread Scheduling for Multiprogrammed Multiprocessors.” Proceedings of the Tenth Annual ACM Symposium on Parallel Algorithms and Architectures. ACM, New York, 1998, pp. 119–29. ISBN 0-89791-989-0.