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

How to Debug Native OutOfMemory in JRockit

This is the first time that I have seen the following messages:

Caused By: java.lang.OutOfMemoryError: CG #210992 (2) weblogic/management/configuration/DomainMBeanImpl$Helper.getChildren()Ljava/util/Iterator; in generate_code (compilerfrontend.c:537).

Attempting to allocate 6G bytes

There is insufficient native memory for the Java Runtime Environment to continue.

In this article, we will discuss what native memory is and how to debug running out of native memory in JRockit.

Native Memory vs. Heap Memory

There are two types of memory used by JVM and its applications, all of which are allocated from system memory:

• Java Heap
• Java heap is the area of memory used by the JVM to do dynamic memory allocation.
• The amount of memory used for the heap can be controlled by the following command options:
• –Xms2g
• –Xmx2g
• Heap memory can be garbage collected^[4].

• Native Memory
• Internal JVM memory management is, to a large extent, kept off the Java heap and allocated natively in the operating system, through system calls like malloc.   This non-heap system memory allocated by the JVM is referred to as native memory. 
• For JRockit, increasing the amount of available native memory is done implicitly by lowering the maximum Java heap size using –Xmx.

If the heap is too large, it may well be the case that not enough native memory is left for JVM internal usage—bookkeeping, code optimizations, and so on. In that case, the JVM may have no other choice than to throw an OutOfMemoryError from native code (for example, from line 537 of compilerfrontend.c in the previous example).

One example is when several parallel threads perform code optimizations in the JVM. Code optimization typically is one of the JVM operations that consumes the largest amounts of native memory, though only when the optimizing JIT is running and only on a per-method basis.

There are also mechanisms that allow the Java program, and not just the JVM, to allocate native memory, for example through JNI calls. If a JNI call executes a native malloc to reserve a large amount of memory, this memory will be unavailable to the JVM until it is freed.

Code Buffers

JRockit is unique in that it has no bytecode interpreter^[1].  The native code is emitted into a code buffer and executed whenever the function it represents is called.  There are two main problems associated with this compile-only strategy:

• Larger compile-code size
• This problem is mitigated by garbage collecting code buffers with methods no longer in use.
• Long compilation time for large methods
• This problem is solved by having a sloppy mode for the JIT.
• Sometimes JRockit will use a lot of time generating a relatively large method, the typical example being a JSP.
• However, once finished, the response time for accessing that JSP will be better than that of an interpreted version.

The problem of running out of memory for metadata in JRockit is not that different from the one in HotSpot, except for that it is native memory instead of heap memory. There are, however, two differences:

• Cleaning up stale metadata is always enabled by default in JRockit
• UseCodeGC = true (default)
• Allow GC of discarded compiled code
• FreeEmptyCodeBlocks = true (default)
• Free unused code memory
• There is no fixed size limit, be default, for the space used to store metadata

JRCMD^[2]

When JRockit runs out of native memory and throws an OOM exception, JRCMD can be used for debugging.  JRCMD is a small command-line tool that can be used to interact with a running JRockit instance.  And it can be used to track native memory usage.

There is no need to pre-configure the JVM or the application to be able to later attach the tool. Also, the tool add virtually no overhead, making it suitable for use in live production environments.

The tools.jar in the JDK contains an API for attaching to a running JVM—the Java Attach API. This framework is utilized by JRCMD to invoke diagnostic commands.

For debugging OOM, you can invoke jrcmd with print_memusage command with displayMap argument:

$ ./jrcmd 411 print_memusage displayMap
411:
Total mapped                  3641460KB           (reserved=178564KB)
-              Java heap      2097152KB           (reserved=0KB)
-              GC tables        70156KB
-          Thread stacks        45876KB           (#threads=132)
-          Compiled code        65536KB           (used=45010KB)
-               Internal         1672KB
-                     OS       394836KB
-                  Other       544088KB
-            Classblocks        27392KB           (malloced=26718KB #62502)
-        Java class data       393728KB           (malloced=388547KB #294025 in 62502 classes)
- Native memory tracking         1024KB           (malloced=168KB #10)


+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
    OS                          *java    r x 0x0000000000400000.(     76KB)
    OS                          *java    rw  0x0000000000612000.(      4KB)
    OS                        *[heap]    rw  0x000000001e8a0000.( 284976KB)
THREAD                      Stack 457    rwx 0x000000004007c000 (      8KB)
THREAD                      Stack 457        0x000000004007e000 (     12KB)

In the header section, the first column contains the name of a memory space (i.e., "Java Heap") and the second column shows how much memory is mapped for that space. The third column contains details.

In the map section, the first column shows the category of memory chunks:

• THREAD: Thread related, for example thread stacks.
• INT: Internal use, for example pointer pages.
• HEAP: Chunk used by JRockit for the Java heap.
• OS: Mapped directly from the operating system, such as third party DLLs or shared objects.
• MSP: Memory space. A memory space is a native heap with a specific purpose, for example native memory allocation inside the JVM.
• GC: Garbage collection related, for example live bits.
• CODE: compiled code

When tracking native memory leaks, it is useful to look at how much the memory usage changes over time.  You can do by establishing a baseline first:

$jrcmd 411 print_memusage scale=M baseline

The argument baseline is used to establish a point from which to start measuring.  The scale argument modifies the unit of the amounts of memory in the printout (default is KB).  Once print_memusage is executed with the baseline argument, subsequent calls will include differentials against the baseline.  This can facilitate the monitoring of memory usage changes over time.

References

1. Oracle JRockit - The Definitive Guide by Marcus Hirt and Marcus Lagergren
2. Diagnostic Commands (JRCMD)
3. JNI calls (Wikipedia)
4. Understanding Garbage Collection (XML and More)
5. Where did all of these ConstPoolWrapper objects come from?!

JRockit Version Information

There are at least three version  numbers of interest for each JRockit release:

1. JRockit JVM version
2. JDK version
3. Mission Control version

JDK Version and JVM Version

To obtain the version number of the JDK and JVM, you execute the following command from the prompt:

• java -version

For example, this is displayed from my system:

java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07) 
Oracle JRockit(R) (build R28.1.3-11-141760-1.6.0_24-20110301-1432-linux-x86_64, compiled mode)

Each version of the JRockit JVM is built for several different JDKs. Oracle JRockit R28 supports the following Java versions:

• J2SE 5.0
• Java SE 6

Ensure that your application complies with the Java specification corresponding to the Oracle JRockit release that you use.

You can find two pieces of information from the above output:

1. JDK version
• "1.6.0_24" is the JDK version being bundled with the JVM
• In other words, Java 1.6 is supported and it is bundled with the JDK classes from update 24-b07.
2. JRockit JVM version
• R28.1.3-11-141760-1.6.0_24-20110301-1432-linux-x86_64
• Version number:  R28.1.3
• Build number:  11
• Change number:  141760
• Date and Time: 20110301-1432 (in  compact ISO 8601 format)
• JVM is built for:
• OS: Linux
• CPU Architecture: x86_64

Mission Control Version

The JRockit Mission Control tools suite includes tools to monitor, manage, profile, and eliminate memory leaks in your Java application without introducing the performance overhead normally associated with tools of this type.

The version number for JRockit Mission Control can be gathered from command prompt by executing:

• jrmc -version

The output should look like this:

Oracle JRockit(R) Mission Control(TM) 4.0 (for JRockit R28.0.0)
  java.vm.version = R28.1.3-11-141760-1.6.0_24-20110301-1432-linux-x86_64
  build = M4.0.1-19
  chno = 134472
  jrmc.fullversion = 4.0.1
  jrmc.version = 4.0
  jrockit.version = R28.0.0
  year = 2010

The frst line tells us what version of Mission Control this is and what version of JRockit it was created for. The java.vm.version line tells us what JVM Mission Control is actually running on.

References

1. Oracle JRockit--The Defnitive Guide
2. J2SE 5.0
3. Java SE 6
4. Oracle® JRockit Installation and Upgrade Guide Release R28
5. JRockit Mission Control
6. Oracle® JRockit Command-Line Reference Release R28