JRockit: Out-of-the-Box Behavior of Four Generational GC's

In [2], we have presented four Generational GCs in JRockit:

• -Xgc:gencon
• -Xgc:genpar
• -Xgc:genconpar
• -Xgc:genparcon

In this article, we will examine their Out-of-the-box (OOTB)^[7] behaviors, especially on adaptive (or automatic) memory management in JRockit.

Adaptive Memory Management

JRockit was the first JVM to recognize that adaptive optimizations based on feedback could be applied to all subsystems in the runtime,^[1] which include:

• Code Generation
• Memory Management
• Threads and Synchronization

In this article, we will focus mainly on the memory management of R28. In R28, JRockit adaptively modifies many aspects of the garbage collection, but to a lesser extent than R27.^[1]

Adaptive optimizations based on runtime feedback work in this way:^[1] In the beginning, these changes are fairly frequent, but after a warm-up period and maintained steady-state behavior, the idea is that the JVM should settle upon an optimal algorithm. If, after a while, the steady-state behavior changes from one kind to another, the JVM may once again change strategies to a more optimal one.

So, JRockit may heuristically change garbage collection behavior at runtime, based on feedback from the memory system by doing:

• Changing GC strategies
• Automatic heap resizing
• Getting rid of memory fragmentation at the right intervals
• Recognizing when it is appropriate to "stop the world"
• Changing the number of garbage collecting threads

-Xverbose:gc flag

To investigate the OOTB behavior of four mentioned Generational GC's (see also [2]), we have used:

• -Xverbose:gc flag

Typically, the log shows things such as garbage collection strategy changes and heap size adjustments, as well as when a garbage collection take place and for how long.

OOTB Behavior

The OOTB behavior of four Generational GC's was investigated using one of our benchmarks, which has the following characteristics (see also [3,4]):

• High churning rate
• Allocating large objects

Here are the Average Response Time (ART; on relative scale) of four different GC strategies:

• -Xgc:genpar
• Baseline
• -Xgc:gencon
• -3.21%
• -Xgc:genconpar
• -36.56%
• -Xgc:genparcon
• -17.60%

After tests, it turns out that the default throughput GC (i.e., genpar) performs the best while other low-pausetimes GC's lag behind. There are a couple of reasons:

• Large live data set
• Our benchmark has large live data size (i.e., 1,471,425 KB) and we have assigned it a relative tight heap space (i.e., 2GB).
• Concurrent sweeping phase cannot keep up with the workload generated from marking phase
• This can be manifested by the following facts:
• Emergency parallel sweep requested for both genconcon and genparcon
• But, not genconpar

Changing GC Strategies at Runtime

The mark-and-sweep algorithm consists of two phases:[1,5,8]

1. Mark phase
• In which, it finds and marks all accessible objects (or live objects)
2. Sweep phase
• In which, it scans through the heap and reclaims all the unmarked objects

In the GC log of both gencon and genparcon, we have seen the following messages:

gencon

• [INFO ][memory ][Thu Jan 9 06:02:12 2014][1389247332488][25536] [OC#6] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.

genparcon

• [INFO ][memory ][Wed Jan 8 21:15:00 2014][1389215700143][24163] [OC#1] Changing GC strategy from: genparcon to: genparpar, reason: Emergency parallel sweep requested.

Possible reasons could be that:

Sweeping and compaction (JRockit uses partial compaction to avoid fragmentation) tend to be more troublesome for parallelization. When you allow Java threads to be run concurrently in the sweep phase, it makes sweeping run longer and slower because more bookkeeping and/or synchronization needed. Also, using fewer GC threads introduces the issue that the garbage collector cannot keep up with the growing set of dead objects.

Conclusions

Ideally, an adaptive runtime would never need tuning at all, as the runtime feedback alone would determine how the application should behave for any given scenario at any given time. However, the computational complexity of mark-and-sweep algorithm is both a function of the amount of live data on the heap (for mark) and the actual heap size (for sweep). Depending on the amount of live data on the heap and system configuration, the OOTB behavior of chosen Generational GC's may or may not be able to keep up the garbage collections.

It is often argued that automatic memory management can slow down execution for certain applications to such an extent that it becomes impractical. This is because automatic memory management can introduce a high degree of non-determinism to a program that requires short response times. And, there are more bookkeeping or overhead. For example, it would need an Old GC to change garbage collection strategies. To avoid this, some manual tuning may be needed to get good application performance.

Before attempting to tune the performance of an application, it is important to know where the bottlenecks are. That way no unnecessary effort is spent on adding complex optimizations in places where it doesn't really matter.

References

1. Oracle JRockit- The Definitive Guide
2. JRockit: Parallel vs Concurrent Collectors (Xml and More)
3. JRockit: A Case Study of Thread Local Area (TLA) Tuning (Xml and More)
4. JRockit: Thread Local Area Size and Large Objects (Xml and More)
5. Mark-and-Sweep Garbage Collection
6. JRockit: All Posts on "Xml and More"
7. The Unspoken - The Why of GC Ergonomics (Jon Masamitsu's Weblog)
8. Mark and Sweep (MS) Algorithm (Xml and More)

JRockit: Analyzing GC With JRockit Verbose Output (-Xverbose:memdbg)

Before any JRockit performance tuning, you need to assess the sizes of the objects allocated by your application.^[4] One way to access live data size is to view object allocation statistics from the GC log file.

In this article, we will show you how to access object allocation statistics by enabling the JRockit verbose output:

• -Xverbose:memdbg

Verbose memdbg Log Module^[1]

The -Xverbose:memdbg log module is an alias that starts several memory-related log modules to provide a complete picture of the memory management. The memdbg log module sets the memory module to the debug level. This information can also be obtained by setting:

• -Xverbose:memory=debug

The overhead of the verbose memdbg output is low, which means it can be used in production environments. For example, after enabling -Xverbose:memdb, the overhead has caused the Average Response Time (ART) to deteriorate by 2.25% using our benchmark.

Understanding Verbose Output

After setting the memory module to the debug level, JRockit provides us tons of information. To understand its formats, read [1]. Here we will focus only on OC's (old collections). For example, here is a typical output from the memory log module at the debug level:

[DEBUG][memory ][06310] [OC#41] GC reason: Allocation request failed (1048592 bytes).
[DEBUG][memory ][06310] [OC#41] 2607.371: OC started.
[INFO ][alloc  ][06310] [OC#41] Pending requests at 'Before OC' - Total: 1, TLAs: 0(approx 0 bytes), objects: 1 (1048592 bytes). Max age: 0.
[INFO ][compact][06310] [OC#41] Compaction reason: Normal.
[INFO ][compact][06310] [OC#41] Compacting 128 of 4096 parts at index 384. Compaction type is internal. Exceptional: No.
[INFO ][compact][06310] [OC#41] Compaction area start: 0x8c000000, end: 0x90000000.
Timeout: 411.471 ms.
[INFO ][compact][06310] [OC#41] Compactset limit (per thread): 316839 (dynamic), not using matrixes.
[DEBUG][memory ][06310] [OC#41] Starting parallel marking phase.
[DEBUG][memory ][06310] [OC#41] SemiRef phase WeakJNIHandles run in single threadedmode.
[DEBUG][memory ][06310] [OC#41] SemiRef phase ClassConstraints run in single threaded mode.
[DEBUG][memory ][06310] [OC#41] SemiRef phase FinalMemleak run in single threaded mode.
[DEBUG][memory ][06310] [OC#41] Adding 48 temporary work packets to permanent pool,now 811 packets.
[DEBUG][memory ] [OC#41] Total mark time: 307.204 ms.
[DEBUG][memory ] [OC#41] Ending marking phase.
[DEBUG][memory ] [OC#41] Starting parallel sweeping phase.
[INFO ][nursery] [OC#41] Setting keepAreaMarkers[0] to 0xc9872bc0.
[INFO ][nursery] [OC#41] Setting keepAreaMarkers[1] to 0xcc97f7a0.
[INFO ][nursery] [OC#41] Setting keepAreaMarkers[2] to 0xd20f6088.
[INFO ][nursery] [OC#41] Next keeparea will start at 0xcc97f7a0 and end at 0xd20f6088.
[INFO ][nursery] [OC#41] Nursery size increased from 0KB to 120414KB. Nursery list consists of 2760 parts.
[INFO ][nursery] [OC#41] Average part size: 44KB. Contraharmonic mean (CHM):946KB. CHM per part: 0KB. Normalized CHM: 0.007856.
[DEBUG][memory ][ [OC#41] Total sweep time: 159.954 ms.
[DEBUG][memory ] [OC#41] Ending sweeping phase.
[INFO ][nursery] [OC#41] Nursery size remains at 120414KB. Nursery list consists of 2760 parts.
[INFO ][nursery] [OC#41] Average part size: 44KB. Contraharmonic mean (CHM):946KB. CHM per part: 0KB. Normalized CHM: 0.007856.
[INFO ][alloc  ] [OC#41] Satisfied 0 object and 0 tla allocations. Pending requests went from 1 to 1.
[INFO ][compact] [OC#41] Average compact time ratio (move phase/total time):0.655049.
[INFO ][compact] [OC#41] Compaction time, total: 158.705 ms (target 411.471 ms).
[INFO ][compact] [OC#41] Compaction moved 1295486 objects and left 349 objects. Total moved size 64028976B.
[INFO ][compact] [OC#41] Compaction added 3047752B of free memory in 2 parts.
[INFO ][compact] [OC#41] Compaction time, move phase: 58.023 ms (target 205.735 ms).
[INFO ][compact] [OC#41] Compaction time, update phase: 100.669 ms (target 205.735 ms).
[INFO ][compact] [OC#41] Found 3350566 references. Internal: 1807732  External: 1542834.
[INFO ][compact] [OC#41] Updated 3339159 references. Internal: 1807048  External: 1532111.
[INFO ][alloc  ] [OC#41] Pending requests at 'After OC' - Total: 1, TLAs: 0 (approx 0 bytes), objects: 1 (1048592 bytes). Max age: 1.
[DEBUG][memory ] [OC#41] Page faults before OC: 1, page faults after OC: 1, pages in heap: 524288.
[DEBUG][memory ] [OC#41] Nursery size after OC: 120414KB. (Free: 120371KB Parts: 2760)
[INFO ][memory ] [OC#41] 2607.371-2607.928: OC 1890153KB->1756549KB (2097152KB), 0.558 s, sum of pauses 472.469 ms, longest pause 472.469 ms.

Note that we have used the following JRockit options:

• -Xverbose:memdbg -Xverbose:gc -Xverbosedecorations=level,module,timestamp,millis,pid

GC Reason

Old collections can be triggered by different events. For example, in the above example, it shows the reason for OC#41 is:

• Allocation request failed

There are other events can trigger an OC. For example, it can be:

• GC reason: Artificial, description: Print Heap Summary
• GC reason: Artificial, description: Print Heap Diagnostics

From our GC log file, we have found the following OC statistics (total: 235)

• GC reason: Allocation request failed (total: 219)
• GC reason: Artificial, description: Print Heap Summary (total: 8)
• GC reason: Artificial, description: Print Heap Diagnostics (total: 8)

Among all events, you can count those artificial heap printing events as the overhead of enabling:

• -Xverbose:memdbg

References

1. Understanding Verbose Output
2. JRockit: A Case Study of Thread Local Area (TLA) Tuning (Xml and More)
3. JRockit: Thread Local Area Size and Large Objects (Xml and More)
4. Analyzing the Performance Impact of Memory Utilization and Garbage Collection

JRockit: A Case Study of Thread Local Area (TLA) Tuning

Increasing the Thread Local Area (TLA) size is beneficial for multi-threaded applications where each thread allocates a lot of objects. Increasing the TLA size is also beneficial when the average size of the allocated objects is large, as this allows larger objects to be allocated in the TLAs.

In this article, we will present a case of TLA tuning using an application with the following characteristics:

• A multi-threaded application
• Allocating a lot of objects
• Allocating large objects 

TLA Basics

Without much ado, see [1] for the differences between JRockit's large-object implementations between pre- and post-R28.   The version of JRockit used in this article is R28.2.5.  For this version, TLA sizes can be tuned using the following option:

• -XXtlaSize:min=size,preferred=size,wasteLimit=size

Chaning Default TLA Sizes

For our Linux system, the default TLA settings are:

• min=2k
• preferred=16k
• wasteLimit=2k

To tune for better performance, read [2,4] for advice.  For example, one recommendation offered by Oracle is:

• Setting  -XXtlaSize:wasteLimit to the same value as -XXtlaSize:min.

After trials and errors, we have found the following TLA settings to be better than the defaults:

• -XXtlaSize:min=8k,preferred=512k,wasteLimit=8k

Performance Comparison: Default vs. TLA Tuned

Looking at different KPIs, we have found the application's performance improved by 5.9% in Average Response Time (ART) and 3.32% in 90% Response Time.  Better performance is achieved by reducing pause time % in GC and Total CPU % at the expense of total memory footprint (-1.6%).

Conclusion

As the benchmark results show, you can tune your application's performance by tuning TLA sizes. The performance improvement may vary based on your JRockit versions and system capabilities. But, before you do any fine tuning, read [2, 4] first.

Finally, be warned that options that are specified with -XX are not stable and are not recommended for casual use. These options are subject to change without notice.^[3]

References

1. JRockit: Thread Local Area Size and Large Objects
2. Optimizing Memory Allocation Performance (Section 4.4 of this pdf)
3. -XXtlaSize Parameters
4. Oracle JRockit- The Definitive Guide
5. finding L2 cache size in Linux