Tuesday Feb 16, 2016

Using NMT with custom JVM launcher

I recently worked with a customer, facing problem in using Native Memory Tracker with their custom JVM launcher created using the JNI API JNI_CreateJavaVM, and learned how NMT can be enabled when used with the custom JVM launchers (non 'java' launchers). This blog post shares details on how that can be done.

Let's start with the following JNI code example where I am passing the JVM option -XX:+NativeMemoryTracking=detail as an argument while creating the JVM with
JNI_CreateJavaVM call. -XX:+NativeMemoryTracking=detail option should enable the Native Memory Tracker at the detail level.

JavaVM *javaVM;       
JNIEnv *env;       
// VM initialization arguments
JavaVMInitArgs vmArgs;
JavaVMOption* options = new JavaVMOption[1];
options[0].optionString = "-XX:+NativeMemoryTracking=detail";
vmArgs.version = JNI_VERSION_1_8;
vmArgs.nOptions = 1;
vmArgs.options = options;
vmArgs.ignoreUnrecognized = false;
//Create Java VM
JNI_CreateJavaVM(&javaVM, (void**)&env, &vmArgs);
delete options;


JAVA_INCLUDES=-I$(JAVA_HOME)/include/ -I$(JAVA_HOME)/include/$(JAVA_OS)/ -L$(JAVA_HOME)/jre/lib/amd64/server
g++ jnicode.cpp $(JAVA_INCLUDES) -ljvm

When this program is compiled using the above compile command, and executed, it reports the following error:

Java HotSpot(TM) 64-Bit Server VM warning: Native Memory Tracking did not setup properly, using wrong launcher?

The reason for this behavior is that the Native Memory Tracker requires an environment variable to be set for the process before the JVM can be initialized and created. That environment variable is NMT_LEVEL_<pid> where <pid> is the identifier of the process. Also, please note that since this environment variable should already be set before the JVM gets initialized, we need to dynamically load the JVM shared library at runtime after setting the env variable .

Here's the sample code showing how we can do that:

// env variable to be set for NMT
const char*  NMT_Env_Name    = "NMT_LEVEL_";
const int TOTAL_LEN = strlen(NMT_Env_Name)+20;
char *nmtEnv = (char*)calloc(TOTAL_LEN,1);
snprintf(nmtEnv,TOTAL_LEN, "%s%d", NMT_Env_Name, getpid());
// Set the env variable
setenv(nmtEnv, "detail", 1);

//Dynamically load libjvm.so
const char* jvmpath = "<path to libjvm.so>/libjvm.so";
void* libjvm = dlopen(jvmpath, RTLD_NOW + RTLD_GLOBAL);
if (libjvm == NULL) {
 printf("Could not open libjvm.so\n");
 return -1;

// VM initialization arguments
JavaVMInitArgs vmArgs;
JavaVMOption* options = new JavaVMOption[1];
options[0].optionString = "-XX:+NativeMemoryTracking=detail";
vmArgs.version = JNI_VERSION_1_8;
vmArgs.nOptions = 1;
vmArgs.options = options;
vmArgs.ignoreUnrecognized = false;

// get a handle to JNI_CreateJavaVM function in the dynamically loaded JVM
CreateJavaVM_t CreateJavaVM;
CreateJavaVM = (CreateJavaVM_t)dlsym(libjvm, "JNI_CreateJavaVM");
// Create the JVM
JavaVM *javaVM;
JNIEnv *jniEnv;
long flag = CreateJavaVM(&javaVM, (void**)&jniEnv, &vmArgs);
delete options;


g++ jnivm.cc $(JAVA_INCLUDES) -ldl

In the above example code, I am setting env variable NMT_LEVEL_<pid> and dynamically loading libjvm.so after setting this env variable. Note that I removed -ljvm from the g++ options so as not to load the JVM shared library at the process load time. With these simple changes, NMT can be used with the custom JVM launchers.

Wednesday Dec 09, 2015

VM warning: PICL (libpicl.so.1) is missing

To increase the compiled code performance, following two fixes were integrated into JDK 8u40 and 7u80. With these changes, HotSpot uses PICL library available on Sparc Platform to get the CPU L2 cache line data size. This information can be used by the Compiler to optimize the generated compiled code and thus improve the runtime performance.

1. JDK-8056124: Hotspot should use PICL interface to get cacheline size on SPARC
Changeset: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/rev/63934ec778a2

2. JDK-8059200:Promoted JDK9 b31 for Solaris-amd64 fails (Error: dl failure on line 744, no picl library) on Solaris 11.1
Changeset: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/rev/d0e59d57dda2

This enhancement attempts to load the PICL library dynamically, and if the library is not found on the system it issues the following warning and continues with the execution of the process:

Java HotSpot(TM) Server VM warning: PICL (libpicl.so.1) is missing.
Performance will not be optimal.

Please note that this warning just indicates that the JVM could not load the PICL library so it won't be able to turn on some of the JIT Compiler optimizations that require the cache line data size information. It does not stop the Java process, or impact the process in any other way. Also, note that this is not a Java bug. The warning message is just intended to inform the user that the platform it is running on does not have the PICL library.

Wednesday Oct 28, 2015

JVM hang with CMS collector

This blog post was long due but better late than never. Sometime back I worked on an interesting GC problem which initially looked like an issue with the JVM runtime system. I am talking about 'JDK-8085965: VM hangs in C2Compiler'. This bug has been fixed in JDK 9 and 8u45+. In this post, I want to share interesting symptoms of this bug, and the troubleshooting steps taken that helped in getting to the root of the problem.

This report came in as a JVM hang when running with the CMS collector. Looking at the core file revealed that the JVM was in the '_synchronizing' state at that point.

(gdb) print SafepointSynchronize::_state
$1 = SafepointSynchronize::_synchronizing
(gdb) print SafepointSynchronize::_waiting_to_block
$2 = 1

It was waiting for one thread to come to safe-point state and block.

And the only thread running at that time was the Compiler thread. Stack trace of the Compiler thread:
(gdb) where
#0  Dependencies::find_finalizable_subclass (k=0x101047428)
#1  0x00007fd6804a38ee in ciInstanceKlass::has_finalizable_subclass (this=0x7fd67913e950)
#2  0x00007fd6809c28fb in Parse::call_register_finalizer (this=0x7fd6395405a0)
#3  0x00007fd6809c2fb9 in Parse::return_current (this=0x101047428, value=0x0)
#4  0x00007fd6809cf526 in Parse::do_one_bytecode (this=0x101047428)    
#5  0x00007fd6809c17d8 in Parse::do_one_block (this=0x7fd6395405a0)
#6  0x00007fd6809c1a57 in Parse::do_all_blocks (this=0x7fd6395405a0)
#7  0x00007fd6809c5fe9 in Parse::Parse (this=0x7fd6395405a0, caller=<optimized out>, parse_method=<optimized out>, expected_uses=5377)
#8  0x00007fd6804784e8 in ParseGenerator::generate (this=0x7fd63004dd60, jvms=0x7fd61c402f40)
#9  0x00007fd6805eea36 in Parse::do_call (this=0x7fd6395409c0)
#10 0x00007fd6809cf5aa in Parse::do_one_bytecode (this=0x101047428)
#11 0x00007fd6809c17d8 in Parse::do_one_block (this=0x7fd6395409c0)
#12 0x00007fd6809c1a57 in Parse::do_all_blocks (this=0x7fd6395409c0)
#13 0x00007fd6809c5fe9 in Parse::Parse (this=0x7fd6395409c0, caller=<optimized out>, parse_method=<optimized out>, expected_uses=5377)

The klass* passed to find_finalizable_subclass() was: 0x101047428

(gdb) info frame
Stack level 0, frame at 0x7fd639540240:
 rip = 0x7fd6805955a0 in Dependencies::find_finalizable_subclass

(gdb) print k
$1 = (Klass *) 0x101047428

(gdb) print *$1
$2 = {<Metadata> = {<MetaspaceObj> = {<No data fields>}, _vptr.Metadata =
0x7fd680fc9670 <vtable for InstanceKlass+16>}, _layout_helper = 16,
  _super_check_offset = 64, _name = 0x7fd618009850, _secondary_super_cache =
 0x100009608, _secondary_supers = 0x7fd668848a88, _primary_supers = {
    0x100000f28, 0x100009418, 0x1000097f0, 0x101047428, 0x0, 0x0, 0x0, 0x0},
 _java_mirror = 0xa77b4b40, _super = 0x1000097f0, _subklass = 0x0,
   _next_sibling = 0x101047428, _next_link = 0x0, _class_loader_data =
 0x7fd618003ab0, _modifier_flags = 1, _access_flags = {_flags = 536870913},
   _last_biased_lock_bulk_revocation_time = 0, _prototype_header = 0x5,
 _biased_lock_revocation_count = 0, _trace_id = 1685520384,
   _modified_oops = 0 '\000', _accumulated_modified_oops = 0 '\000',
 _shared_class_path_index = -1}
(gdb) x/s 0x7fd618009850+8
 0x7fd618009858: "sun/reflect/GeneratedMethodAccessor1389"

 _next_sibling = 0x101047428

The next_sibling in this case was the same as the klass itself. So, the compiler thread was stuck in the following loop:

 1187 Klass* Dependencies::find_finalizable_subclass(Klass* k) {
 1188   if (k->is_interface())  return NULL;
 1189   if (k->has_finalizer()) return k;
 1190   k = k->subklass();
 1191   while (k != NULL) {
 1192     Klass* result = find_finalizable_subclass(k);
 1193     if (result != NULL) return result;
 1194     k = k->next_sibling(); 
 1195   }
 1196   return NULL;
 1197 }

Then we did another run with the failing program using TraceClassLoading and TraceClassUnloading JVM options. From the core file of this run, found that VM was stuck while going over a circular siblings list. Note that the subklasses of a Klass are maintained using the _next_sibling field of its first _subklass.

Here's the klass and subklasses chain built from the core file:

super class sun/reflect/SerializationConstructorAccessorImpl - 0x1001acec0
   |--subklasses chain
0x1010f0c30- sun/reflect/GeneratedSerializationConstructorAccessor224->
0x1010f2430- sun/reflect/GeneratedSerializationConstructorAccessor218->

The GC logs generated with TraceClassLoading and TraceClassUnloading options had:

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor216 0x000000010110b830]

So, GeneratedSerializationConstructorAccessor216 was unloaded from address 0x10110b830, and sun/reflect/GeneratedMethodAccessor94 got loaded at the same address. But the link to GeneratedSerializationConstructorAccessor216 in the siblings list was not updated after this class was unloaded, and that corrupted the subKlasses chain.

That made me look at the other JVM options used for this failing program. hs_err file showed that -Xnoclassgc was being used to turn off the class unloading but the logs indicated that classes were still getting unloaded. From that point, this mystery was not very hard to solve.

In JDK8, CMSClassUnloadingEnabled option which is used to control the class-unloading in CMS collector, was enabled by default. And this problem was occurring due to the conflicting values getting set for CMSClassUnloadingEnabled and ClassUnloading options. One phase of the class-unloading which is common to the other collectors too that updates subkalsses/siblings links is performed only when ClassUnloading option is enabled. So when -Xnoclassgc or -XX:-ClassUnloading are specified on the command line, due to this bug CMSClassUnloadingEnabled stays enabled and classes get unloaded but that common step gets skipped which corrupts the class hierarchy links leading to hangs or crashes.

The fix was simple - disable CMS class unloading options when -Xnoclassgc or -XX:-ClassUnloading are specified.

There is a similar bug open for G1 collector which is being worked and is targeted for JDK9:
    JDK-8114823: G1 doesn't honor request to disable class unloading

Thursday Sep 10, 2015

Why do I get message "CodeCache is full. Compiler has been disabled"?

JVM JIT generates compiled code and stores that in a memory area called CodeCache. The default maximum size of the CodeCache on most of the platforms is 48M. If any application needs to compile large number of methods resulting in huge amount of compiled code then this CodeCache may become full. When it becomes full, the compiler is disabled to stop any further compilations of methods, and a message like the following gets logged:

Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled.
Java HotSpot(TM) 64-Bit Server VM warning: Try increasing the code cache size using -XX:ReservedCodeCacheSize=
Code Cache  [0xffffffff77400000, 0xffffffff7a390000, 0xffffffff7a400000) total_blobs=11659 nmethods=10690 adapters=882 free_code_cache=909Kb largest_free_block=502656

When this situation occurs, JVM may invoke sweeping and flushing of this space to make some room available in the CodeCache. There is a JVM option UseCodeCacheFlushing that can be used to control the flushing of the Codeache. With this option enabled JVM invokes an emergency flushing that discards older half of the compiled code(nmethods) to make space available in the CodeCache. In addition, it disables the compiler until the available free space becomes more than the configured CodeCacheMinimumFreeSpace. The default value of CodeCacheMinimumFreeSpace option is 500K.

UseCodeCacheFlushing is set to false by default in JDK6, and is enabled by default since JDK7u4. This essentially means that in jdk6 when the CodeCache becomes full, it is not swept and flushed and further compilations are disabled, and in jdk7u+, an emergency flushing is invoked when the CodeCache becomes full. Enabling this option by default made some issues related to the CodeCache flushing visible in jdk7u4+ releases. The following are two known problems in jdk7u4+ with respect to the CodeCache flushing:

1. The compiler may not get restarted even after the CodeCache occupancy drops down to almost half after the emergency flushing.
2. The emergency flushing may cause high CPU usage by the compiler threads leading to overall performance degradation.

This performance issue, and the problem of the compiler not getting re-enabled again has been addressed in JDK8. To workaround these in JDK7u4+, we can increase the code cache size using ReservedCodeCacheSize option by setting it to a value larger than the compiled-code footprint so that the CodeCache never becomes full. Another solution to this is to disable the CodeCache Flushing using -XX:-UseCodeCacheFlushing JVM option.

The above mentioned issues have been fixed in JDK8 and its updates. Here's the list of the bugs that have been fixed in jdk8 and 8u20 that address these problems:
    * JDK-8006952: CodeCacheFlushing degenerates VM with excessive codecache freelist iteration (fixed in 8)
    * JDK-8012547: Code cache flushing can get stuck without completing reclamation of memory (fixed in 8)
    * JDK-8020151: PSR:PERF Large performance regressions when code cache is filled (fixed in 8)
    * JDK-8029091 Bug in calculation of code cache sweeping interval (fixed in 8u20)
    * 8027593: performance drop with constrained codecache starting with hs25 b111 (fixed in 8)

Wednesday Apr 22, 2015

Throughput collector and PrintTenuringDistribution option

This is going to be a very short blog post. The inspiration for this post is a customer report that the PrintTenuringDistribution option does not show age information with the throughput collector (Parallel or Parallel Old GC).

2.798: [GC
Desired survivor size 11534336 bytes, new threshold 7 (max 15)
[PSYoungGen: 67584K->9802K(78848K)] 67584K->9810K(254976K), 0.0467029 secs]
[Times: user=0.07 sys=0.02, real=0.05 secs]
3.604: [GC
Desired survivor size 11534336 bytes, new threshold 7 (max 15)
[PSYoungGen: 77386K->11156K(146432K)] 77394K->11236K(322560K), 0.0436806 secs]

Well, this is the expected behavior and is not a bug. Throughput collector does not use the age table like the other collectors do. And due to that reason, the age histogram information is not printed with the throughput collector. With the throughput collector, we can only see the desired survivor size, threshold age, and the maximum threshold age with PrintTenuringDistribution option.

Friday Apr 17, 2015

Longer Young Collections with JDK7 as Compared to JDK6

If you have moved from JDK 6 to 7 and are observing some increase in the times that young collections take to do their job, then here's a remedy: -XX:+JavaObjectsInPerm.

In JDK7, class statics and interned strings were moved from PermGen to the Java Heap and that may contribute towards a little increase in the young generation collection times. There is an option JavaObjectsInPerm which when enabled reverts that change i.e. class statics and interned strings get allocated back into the PermGen.

So, if tuning PermGen is not an issue and young gen collection times are bothering you then using -XX:+JavaObjectsInPerm might give some relief. Note that this option is available in jdk7 from 7u80 and was made available as a Diagnostic VM option with this CR: JDK-8048271

Since it is a diagnostic option, it needs to be used with -XX:+UnlockDiagnosticVMOptions.

Please note that this option is not available in JDK8 since PermGen has been completely removed in JDK8. Some more details on the PermGen removal can be read here.

Thursday Apr 02, 2015

Updates to the Java Troubleshooting Guide

Mattis Castegren who is my manager at Oracle, and is the guest writer for this blog post would like to share some details on the Java Troubleshooting Guide. Here's what he has to say:--

With the release of JDK 8, the official Java Troubleshooting Guide got a big overhaul. All pages were looked over and updated for JDK 8, and the two previous guides for the JVM and for Desktop Technologies were merged into one.

In the last month, with the release of 8u40, we have launched the next phase in this project. In this phase, we have added a lot of chapters about the new supportability tools that have been introduced in Java over the last few years.

The biggest new additions are a set of pages on how to use the Java Flight Recorder (JFR). If you haven't used JFR before, you should definitely check out the following chapters:

2.3 What are Java Flight Recordings

2.4 How to Produce a Flight Recording

2.5 Inspect a Flight Recording

These chapters contain step by step instructions on how to record a JFR and also goes through what to look for in a recording to find common issues. The chapters contain lots of screen shots and details on how to interpret the data.

Once you have learned the basics, you can also look at the following two chapters on how to use JFR to debug specific issues:

3.1 Debug a Memory Leak Using Java Flight Recorder

4 Troubleshoot Performance Issues Using JFR

When you have read through these chapters, you will be ready to use this great tool to find bottle necks in your own application.

Other new additions to the troubleshooting guide is a new chapter on how to set up Java for better troubleshooting: Prepare Java for Troubleshooting, as well as a lot of minor updates and clarifications.

Tuesday Feb 03, 2015

Analysis of Strange Hotspot Crashes

In this blog post, I am going to talk about the core file analysis of some strange looking hotspot crashes using gdb and Serviceability Agent debugging tools. At the first glance, these crashes appeared to be caused by some Hotspot Server Compiler issue but in the end these actually turned out to be due to a Linux Kernel bug.

This first crash happened in the compiled code of method SafeHashMap.put()

# Problematic frame:
# J 3575 C2
com.tangosol.util.SafeHashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; (190 bytes) @ 0x00002aaaabda7ffd [0x00002aaaabda7da0+0x25d]
# Core dump written.

I opened the core with gdb and the stack trace of the crashing thread looked like this:

#15 0x00002afd41aa5e7f in JVM_handle_linux_signal (sig=11, info=0x40fd7c90, ucVoid=0x40fd7b60, abort_if_unrecognized=1)
#16 0x00002afd41a9ce13 in signalHandler (sig=11, info=0x40fd7c90, uc=0x40fd7b60)
#17 <signal handler called>
#18 0x00002aaaabda7ffd in ?? ()
#19 0x00000000c005e3c8 in ?? ()
#20 0x00000000c005e3c8 in ?? ()
#21 0x00000000c005e3c8 in ?? ()
#22 0xc005e3c82000cb42 in ?? ()
#23 0x0000000000000007 in ?? ()
#24 0x0000000000000000 in ?? ()

Opened the core file with Serviceability Agent tool too and inspected the addresses present in the above stack trace:

hsdb> whatis 0x00002aaaabda7ffd
Address 0x00002aaaabda7ffd: In code in NMethod for com/tangosol/util/SafeHashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; content: [0x00002aaaabda7da0, 0x00002aaaabda9280),  code: [0x00002aaaabda7da0, 0x00002aaaabda9280),  data: [0x00002aaaabda9280, 0x00002aaaabda9f18),  oops: [0x00002aaaabda9280, 0x00002aaaabda9288),  frame size: 144

hsdb> whatis 0x00000000c005e3c8
Address 0x00000000c005e3c8: In unknown section of Java heap

So, all the above digging confirmed that the crash happened in the compiled code of com.tangosol.util.SafeHashMap.put(). I looked at the assembly of the generated code in gdb:

(gdb) x/610i 0x00002aaaabda7da0
   0x2aaaabda7f83:      mov    $0x2000cbc5,%r9d
   0x2aaaabda7f89:      movabs $0x0,%r11
   0x2aaaabda7f93:      lea    (%r11,%r9,8),%r11
   0x2aaaabda7f97:      mov    0xa8(%r11),%r11
   0x2aaaabda7f9e:      mov    %r11,0x0(%r13)
   0x2aaaabda7fa2:      movl   $0x2000cbc5,0x8(%r13)
   0x2aaaabda7faa:      mov    %r12d,0xc(%r13)
   0x2aaaabda7fae:      mov    %r12,0x10(%r13)
   0x2aaaabda7fb2:      mov    %r12,0x18(%r13)
   0x2aaaabda7fb6:      mov    %r13,%r9
   0x2aaaabda7fb9:      mov    %r14,%r11
   0x2aaaabda7fbc:      mov    %r11d,0x10(%r13)
   0x2aaaabda7fc0:      shr    $0x9,%r9
   0x2aaaabda7fc4:      movabs $0x2aaab9f5b000,%r11
   0x2aaaabda7fce:      mov    %r12b,(%r11,%r9,1)
   0x2aaaabda7fd2:      mov    (%rsp),%r9d
   0x2aaaabda7fd6:      mov    %r9d,0x14(%r13)
   0x2aaaabda7fda:      mov    %r13,%r11
   0x2aaaabda7fdd:      shr    $0x9,%r11
   0x2aaaabda7fe1:      movabs $0x2aaab9f5b000,%r9
   0x2aaaabda7feb:      mov    %r12b,(%r9,%r11,1)
   0x2aaaabda7fef:      lock addl $0x0,(%rsp)
   0x2aaaabda7ff4:      mov    %r10d,0xc(%r13)
   0x2aaaabda7ff8:      movq   %xmm0,%r11
   0x2aaaabda7ffd:      mov    (%r11),%rax  <---crash here, r11 is 0
   0x2aaaabda8000:      mov    %rax,%r11

The thread crashed while accessing the value at an address stored in r11 register. Looking at the value of r11 register:
r11 0x0

r11 contains 0 and accessing the value at null address caused the crash.

Now, if we look at the previous instruction "movq   %xmm0,%r11", value in r11 was copied over from xmm0 register. The value in xmm0 register is 0.

There is a bug in Linux kernel where the xmm registers may get corrupted under certain circumstances. Details on the kernel bug: https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=547893

The machine where this crash was observed:
RELEASE=2.6.18-308.  VERSION=#1 SMP Tue Apr 17 16:41:30 EDT 2012  MACHINE=x86_64

So, the process was running on a machine which is vulnerable to that Linux kernel bug.

Let's take a look at another such Hotspot crash.

# A fatal error has been detected by the Java Runtime Environment:
#  Internal Error (sharedRuntime.cpp:833), pid=26946, tid=1082554688
#  fatal error: exception happened outside interpreter, nmethods and vtable stubs at pc 0x00002aaaab1f5340

Current thread (0x000000001ee9b000):  JavaThread "main" [_thread_in_Java, id=26949, stack(0x0000000040767000,0x0000000040868000)]

Stack: [0x0000000040767000,0x0000000040868000],  sp=0x00000000408631a0,  free space=1008k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xaaa6ea]  VMError::report_and_die()+0x2ba
V  [libjvm.so+0x4f2749]  report_fatal(char const*, int, char const*)+0x59
V  [libjvm.so+0x9a952a]  SharedRuntime::continuation_for_implicit_exception(JavaThread*, unsigned char*, SharedRuntime::ImplicitExceptionKind)+0x33a
V  [libjvm.so+0x91370a]  JVM_handle_linux_signal+0x48a
V  [libjvm.so+0x909c83]  signalHandler(int, siginfo*, void*)+0x43
C  [libpthread.so.0+0xebe0]
J 528 C2 com.sun.org.apache.xerces.internal.impl.xs.opti.SchemaDOMParser.characters(Lcom/sun/org/apache/xerces/internal/xni/XMLString;Lcom/sun/org/apache/xerces/internal/xni/Augmentations;)V (110 bytes) @ 0x00002aaaab607423 [0x00002aaaab606ec0+0x563]

(gdb) where
#0  0x0000003968a30265 in raise ()
#1  0x0000003968a31d10 in abort ()
#2  0x00002b96ba0bbea5 in os::abort (dump_core=true)
#3  0x00002b96ba258af3 in VMError::report_and_die (this=0x40863320)
#4  0x00002b96b9ca0749 in report_vm_error (detail_msg=<optimized out>,
error_msg=<optimized out>, line=<optimized out>, file=<optimized out>)   
#5  report_fatal (file=0x2b96ba2e0330, line=833, message=0x408633b8)   
#6  0x00002b96ba15752a in SharedRuntime::continuation_for_implicit_exception(thread=0x1ee9b000,
    pc=0x2aaaab1f5340, exception_kind=<optimized out>)   
#7  0x00002b96ba0c170a in JVM_handle_linux_signal (sig=11, info=0x408637c0,
ucVoid=0x40863690, abort_if_unrecognized=1)   
#8  0x00002b96ba0b7c83 in signalHandler (sig=11, info=0x408637c0, uc=0x40863690)
#9  <signal handler called>
#10 0x00002aaaab1f5340 in ?? ()
#11 0x00000000fe8bace8 in ?? ()
#12 0x00002aaaab607423 in ?? ()
#13 0x00000000fe94d0a0 in ?? ()
#14 0x00000000fe8bacd0 in ?? ()
#15 0x00000000fe8bacd0 in ?? ()
#16 0x00002aaac0cdd850 in ?? ()
#17 0x0000000000000007 in ?? ()

Inspecting the crashing PC 0x00002aaaab1f5340 with SA:

hsdb> whatis 0x00002aaaab1f5340
Address 0x00002aaaab1f5340: In code in StubRoutines (2) content:
[0x00002aaaab1f4e20, 0x00002aaaab1fa410),  code: [0x00002aaaab1f4e20,
0x00002aaaab1fa410),  data: [0x00002aaaab1fa410, 0x00002aaaab1fa410),  frame
size: 0

Frame #12:

hsdb> whatis 0x00002aaaab607423
Address 0x00002aaaab607423: In code in NMethod for
rnal/xni/Augmentations;)V content: [0x00002aaaab606ec0, 0x00002aaaab6083d8),  code: [0x00002aaaab606ec0, 0x00002aaaab6083d8),  data: [0x00002aaaab6083d8,
0x00002aaaab608e98),  oops: [0x00002aaaab6083d8, 0x00002aaaab6083e8),  frame size: 144

Disassembly around the crashing PC:

0x2aaaab1f5280:      movdqu 0x30(%rdi,%rdx,8),%xmm0
   0x2aaaab1f5286:      movdqu %xmm0,0x30(%rsi,%rdx,8)
   0x2aaaab1f528c:      movdqu 0x20(%rdi,%rdx,8),%xmm1
   0x2aaaab1f5292:      movdqu %xmm1,0x20(%rsi,%rdx,8)
   0x2aaaab1f5298:      movdqu 0x10(%rdi,%rdx,8),%xmm2
   0x2aaaab1f529e:      movdqu %xmm2,0x10(%rsi,%rdx,8)
   0x2aaaab1f52a4:      movdqu (%rdi,%rdx,8),%xmm3
   0x2aaaab1f52a9:      movdqu %xmm3,(%rsi,%rdx,8)
   0x2aaaab1f52ae:      sub    $0x8,%rdx
   0x2aaaab1f52b2:      jge    0x2aaaab1f5280
   0x2aaaab1f52b4:      add    $0x4,%rdx
   0x2aaaab1f52b8:      jl     0x2aaaab1f52d4
   0x2aaaab1f52ba:      movdqu 0x10(%rdi,%rdx,8),%xmm0
   0x2aaaab1f52c0:      movdqu %xmm0,0x10(%rsi,%rdx,8)
   0x2aaaab1f52c6:      movdqu (%rdi,%rdx,8),%xmm1
   0x2aaaab1f52cb:      movdqu %xmm1,(%rsi,%rdx,8)
   0x2aaaab1f52d0:      sub    $0x4,%rdx
   0x2aaaab1f52d4:      add    $0x4,%rdx
   0x2aaaab1f52d8:      jg     0x2aaaab1f5265
   0x2aaaab1f52da:      xor    %rax,%rax
   0x2aaaab1f52dd:      leaveq
   0x2aaaab1f52de:      retq
   0x2aaaab1f52df:      nop
   0x2aaaab1f52e0:      push   %rbp
   0x2aaaab1f52e1:      mov    %rsp,%rbp
   0x2aaaab1f52e4:      mov    %rdx,%rcx
   0x2aaaab1f52e7:      shr    $0x2,%rdx
   0x2aaaab1f52eb:      lea    -0x8(%rdi,%rdx,8),%rdi
   0x2aaaab1f52f0:      lea    -0x8(%rsi,%rdx,8),%rsi
   0x2aaaab1f52f5:      neg    %rdx
   0x2aaaab1f52f8:      jmpq   0x2aaaab1f5370
   0x2aaaab1f52fd:      mov    0x8(%rdi,%rdx,8),%rax
   0x2aaaab1f5302:      mov    %rax,0x8(%rsi,%rdx,8)
   0x2aaaab1f5307:      inc    %rdx
   0x2aaaab1f530a:      jne    0x2aaaab1f52fd
   0x2aaaab1f530c:      test   $0x2,%ecx
   0x2aaaab1f5312:      je     0x2aaaab1f5322
   0x2aaaab1f5314:      mov    0x8(%rdi),%eax
   0x2aaaab1f5317:      mov    %eax,0x8(%rsi)
   0x2aaaab1f531a:      add    $0x4,%rdi
   0x2aaaab1f531e:      add    $0x4,%rsi
   0x2aaaab1f5322:      test   $0x1,%ecx
   0x2aaaab1f5328:      je     0x2aaaab1f5332
   0x2aaaab1f532a:      mov    0x8(%rdi),%ax
   0x2aaaab1f532e:      mov    %ax,0x8(%rsi)
   0x2aaaab1f5332:      xor    %rax,%rax
   0x2aaaab1f5335:      leaveq
   0x2aaaab1f5336:      retq
   0x2aaaab1f5337:      nopw   0x0(%rax,%rax,1)
=> 0x2aaaab1f5340:      movdqu -0x38(%rdi,%rdx,8),%xmm0
   0x2aaaab1f5346:      movdqu %xmm0,-0x38(%rsi,%rdx,8)
   0x2aaaab1f534c:      movdqu -0x28(%rdi,%rdx,8),%xmm1
   0x2aaaab1f5352:      movdqu %xmm1,-0x28(%rsi,%rdx,8)
   0x2aaaab1f5358:      movdqu -0x18(%rdi,%rdx,8),%xmm2
   0x2aaaab1f535e:      movdqu %xmm2,-0x18(%rsi,%rdx,8)
   0x2aaaab1f5364:      movdqu -0x8(%rdi,%rdx,8),%xmm3
   0x2aaaab1f536a:      movdqu %xmm3,-0x8(%rsi,%rdx,8)
   0x2aaaab1f5370:      add    $0x8,%rdx

In the assembly code of the StubRoutine, we can see that the values are being moved to and from xmm registers and the crash happens while accessing value at an address present in rdi register.

rdx 0xffffffffffffffc8
rdi 0x1f8

Machine details where this crash happened:
RELEASE=2.6.18-308.  VERSION=#1 SMP Tue Apr 17 16:41:30 EDT 2012  MACHINE=x86_64

If you encounter such weird looking Hotspot crashes where the cause of the register/memory corruption seems to be unreasonable, please make sure that you are running on a latest patched Linux kernel. Kernels of version older that 2.6.32 may be vulnerable to this kernel bug.

Thursday Dec 18, 2014

Long Class-Unloading Pauses with JDK8

Recently, I came across a report where a user was facing long GC pauses with JDK8. They didn't see this issue while running with JDK7. The problem with jdk8 was that sometimes the class unloading step of CMS-remark phase was taking a very long time to do its job. They were running with large pages enabled with both jdk7 and jdk8.

2014-11-30T01:51:35.632+0000: [GC (CMS Final Remark) [YG occupancy: 292006 K (1179648 K)][Rescan (parallel) , 0.0397261 secs][weak refs processing, 0.0954205 secs][class unloading, 29.2450253 secs][scrub symbol table, 4.9592268 secs][scrub string table, 0.0034572 secs][1 CMS-remark: 1101173K(1835008K)] 1393180K(3014656K), 34.3796360 secs] [Times: user=0.92 sys=0.38, real=34.37 secs]

2014-12-01T02:01:44.452+0000: [GC (CMS Final Remark) [YG occupancy: 550275 K (1179648 K)][Rescan (parallel) , 0.0785401 secs][weak refs processing, 0.0931797 secs][class unloading, 28.0163134 secs][scrub symbol table, 5.2806525 secs][scrub string table, 0.0034023 secs][1 CMS-remark: 1101982K(1835008K)] 1652257K(3014656K), 33.5087749 secs] [Times: user=1.48 sys=0.36, real=33.51 secs]

Now, here if we look closely, there is a huge difference in the times reported for 'user' 'sys' and 'real'. As we all know, 'user' is the amount of CPU time spent in user-mode within the process and 'sys' is the amount of CPU time spent in the kernel within the process. Other processes and the time the process spends blocked does not count towards these two figures. The 'real' time is the total elapsed time including time slices used by other processes and the time the process spends blocked (for example in waiting for I/O to complete, or system is performing memory activities such as paging/swapping).

In this case too, the problem seemed not be with the JVM or more specifically with the class unloading step but more with the GC threads getting blocked out. It turned out that the class unloading phase was causing lot of paging activity to occur at the system level which took away the CPU time from the GC threads.

What changed in the JVM from JDK7 to JDK8 is that in JDK8 we don't have PermGen. Instead we have MetaSpace which is allocated out of native memory space. As I mentioned earlier, the user was running with Large Pages enabled. With JDK7 by using option -XX:+UseLargePages, we get the large pages enabled for the Java Heap as well as for the PermGen. But with jdk8, with the class meta data stored in MetaSpace(native space), we don't get large pages enabled for the MetaSpace by default when we use +UseLargePages.

In this particular case, the system was configured to have higher number of large pages and a limited memory resource was left for the regular small pages. And a limited number of regular pages available for the MetaSpace caused paging activity during the class unloading phase leading to long GC pauses. The solution for this problem was to use -XX:+UseLargePagesInMetaspace that enables the large pages support for the MetaSpace. This avoided the paging activity and the class-unloading times returned to normal.

Please note that UseLargePagesInMetaspace is not enabled by default when UseLargePages is ON. This is intentional and is done to avoid any memory usage regressions. A classloader (and its classes metadata) is stored in a chunk of memory called Metachunk in the MetaSpace. To be able to hand back pages to the system, we have to clean out an entire page. It is possible that there may be many Metachunks of different classloaders present on a page, and that page can be returned to the system only when all the classloaders are dead and their Metachunks are not needed any more. This leads to delayed deallocation of pages and it is a bit more likely with large pages.

Another reason for not turning UseLargePagesInMetaspace option on by default is that we can not use large pages for the CompressedClass space. The problem there is that we can not dynamically grow the number of large pages; we have to pre-commit all the large pages when memory is reserved. CompressedClass space by default is 1GB of reserved memory and committing that 1GB up-front would cause memory usage regressions.

So, if one has the system configured in such a way that a larger part of memory is set aside for large pages and a relatively smaller part for the regular pages, it is likely to observe the above described long GC pauses during the clean up of MetaSpace. In such situation, using UseLargePagesInMetaspace may help resolve the problem.

Wednesday Nov 26, 2014

Increased heap usage with G1 GC

G1 garbage collector is a predictable low pause collector that works efficiently to achieve the low pause time goals. To meet the set pause time goals, G1 tries to:

  • pick only those many old heap regions for the collection-set that it thinks could be collected in the specified goal time
  • adapt the young generation size to contain the collection times within the set goal.

In that effort, however, G1 may end up causing a side effect of increased usage of the Java Heap.

For example, in an experimental run with CMS using a heap size of 8GB, the maximum observed heap usage was around 4GB. But after switching to G1, with -XX:MaxGCPauseMillis=50, the heap usage went up to 6GB. In both the cases, the application load was same.

Part of the CMS GC logs:
2014-11-21T05:18:18.790-0500: 1918944.850: [GC2014-11-21T05:18:18.790-0500: 1918944.850: [ParNew: 32704K->64K(32704K), 0.0698450 secs] 4274067K->4247066K(8388544K), 0.0700480 secs] [Times: user=0.32 sys=0.01, real=0.06 secs]
2014-11-21T05:18:18.864-0500: 1918944.924: [GC [1 CMS-initial-mark: 4247002K(8355840K)] 4247095K(8388544K), 0.1249300 secs] [Times: user=0.12 sys=0.00, real=0.13 secs]
2014-11-21T05:18:18.989-0500: 1918945.050: [CMS-concurrent-mark-start]
2014-11-21T05:18:31.163-0500: 1918957.223: [GC2014-11-21T05:18:31.163-0500: 1918957.223: [ParNew: 32704K->64K(32704K), 0.0365220 secs] 4279706K->4247775K(8388544K), 0.0367530 secs] [Times: user=0.26 sys=0.00, real=0.04 secs]
2014-11-21T05:18:37.588-0500: 1918963.648: [CMS-concurrent-mark: 18.547/18.598 secs] [Times: user=39.03 sys=0.47, real=18.59 secs]
2014-11-21T05:18:37.588-0500: 1918963.648: [CMS-concurrent-preclean-start]
2014-11-21T05:18:37.708-0500: 1918963.768: [CMS-concurrent-preclean: 0.114/0.120 secs] [Times: user=0.13 sys=0.00, real=0.12 secs]
2014-11-21T05:18:37.708-0500: 1918963.768: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2014-11-21T05:18:42.724-0500: 1918968.785: [CMS-concurrent-abortable-preclean: 3.008/5.016 secs] [Times: user=3.34 sys=0.12, real=5.02 secs]
2014-11-21T05:18:42.728-0500: 1918968.789: [GC[YG occupancy: 25109 K (32704 K)]2014-11-21T05:18:42.728-0500: 1918968.789: [Rescan (parallel) , 0.1196710 secs]2014-11-21T05:18:42.848-0500: 1918968.909: [weak refs processing, 0.0002300 secs]2014-11-21T05:18:42.848-0500: 1918968.909: [class unloading, 0.0219670 secs]2014-11-21T05:18:42.870-0500: 1918968.931: [scrub symbol table, 0.0144900 secs]2014-11-21T05:18:42.885-0500: 1918968.945: [scrub string table, 0.0046370 secs] [1 CMS-remark: 4247711K(8355840K)] 4272821K(8388544K), 0.1740580 secs] [Times: user=0.99 sys=0.00, real=0.17 secs]
2014-11-21T05:18:42.903-0500: 1918968.963: [CMS-concurrent-sweep-start]

Part of the G1 GC logs:
  [Times: user=0.40 sys=0.01, real=0.06 secs]
    [Eden: 368.0M(368.0M)->0.0B(372.0M) Survivors: 40.0M->36.0M Heap: 6622.9M(8192.0M)->6259.7M(8192.0M)]
 2014-10-08T04:38:46.675-0400: 1311963.055: [GC pause (young) (initial-mark), 0.0564110 secs]
    [Parallel Time: 51.4 ms, GC Workers: 8]
       [GC Worker Start (ms): Min: 1311963055.7, Avg: 1311963055.7, Max: 1311963055.8, Diff: 0.1]
       [Ext Root Scanning (ms): Min: 6.3, Avg: 11.8, Max: 16.2, Diff: 9.9, Sum: 94.7]
       [Update RS (ms): Min: 3.0, Avg: 4.7, Max: 7.4, Diff: 4.4, Sum: 37.8]
          [Processed Buffers: Min: 2, Avg: 8.8, Max: 18, Diff: 16, Sum: 70]
       [Scan RS (ms): Min: 1.0, Avg: 1.3, Max: 1.4, Diff: 0.5, Sum: 10.0]
       [Object Copy (ms): Min: 29.0, Avg: 33.0, Max: 39.7, Diff: 10.7, Sum: 264.3]
       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
       [GC Worker Total (ms): Min: 50.9, Avg: 51.0, Max: 51.1, Diff: 0.2, Sum: 407.8]
       [GC Worker End (ms): Min: 1311963106.7, Avg: 1311963106.7, Max: 1311963106.9, Diff: 0.2]
    [Code Root Fixup: 0.0 ms]
    [Clear CT: 1.5 ms]
    [Other: 3.6 ms]
       [Choose CSet: 0.0 ms]
       [Ref Proc: 1.8 ms]
       [Ref Enq: 0.1 ms]
       [Free CSet: 0.7 ms]
    [Eden: 372.0M(372.0M)->0.0B(368.0M) Survivors: 36.0M->40.0M Heap: 6631.7M(8192.0M)->6262.8M(8192.0M)]
  [Times: user=0.42 sys=0.01, real=0.05 secs]
 2014-10-08T04:34:59.344-0400: 1311735.724: [GC pause (mixed), 0.0666200 secs]
    [Parallel Time: 60.4 ms, GC Workers: 8]
       [GC Worker Start (ms): Min: 1311735724.4, Avg: 1311735724.5, Max: 1311735724.5, Diff: 0.2]
       [Ext Root Scanning (ms): Min: 10.1, Avg: 13.0, Max: 19.3, Diff: 9.2, Sum: 104.3]
       [Update RS (ms): Min: 0.0, Avg: 4.5, Max: 6.6, Diff: 6.6, Sum: 35.6]
          [Processed Buffers: Min: 0, Avg: 9.1, Max: 20, Diff: 20, Sum: 73]
       [Scan RS (ms): Min: 3.5, Avg: 4.8, Max: 5.1, Diff: 1.6, Sum: 38.7]
       [Object Copy (ms): Min: 37.1, Avg: 37.6, Max: 38.4, Diff: 1.3, Sum: 301.1]
       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
       [GC Worker Total (ms): Min: 60.0, Avg: 60.1, Max: 60.2, Diff: 0.2, Sum: 481.1]
       [GC Worker End (ms): Min: 1311735784.5, Avg: 1311735784.6, Max: 1311735784.7, Diff: 0.2]
    [Code Root Fixup: 0.0 ms]
    [Clear CT: 2.2 ms]
    [Other: 4.0 ms]
       [Choose CSet: 0.1 ms]
       [Ref Proc: 1.9 ms]
       [Ref Enq: 0.0 ms]
       [Free CSet: 0.9 ms]
    [Eden: 372.0M(372.0M)->0.0B(368.0M) Survivors: 36.0M->40.0M Heap: 6633.2M(8192.0M)->6254.9M(8192.0M)]

The reason for this unexpected behaviour is that G1 tries to select minimal number of old regions in the collection-set so that it can do the evacuation pauses within the specified pause time goal. Due to this, it fails to clean up the garbage in the old regions, and hence the increased heap usage.

To overcome this side effect with G1, if one does not have very strict pause time goals, the young generation size can be increased so that most of the die-young objects get collected in the young regions itself and don't get promoted to the old generation. One can also try relaxing the pause time goals so that G1 includes more number of old regions in the collection set and good amount of garbage gets collected with the evacuation pauses.

Friday Oct 10, 2014

Running on a 64bit platform and still running out of memory

It sounds strange that one is running with 64bit JVM but still running out of native memory or Java Heap space. On a 64bit machine, with 64bit JVM we get almost unlimited memory then how is it possible to run out of memory? Well, it may happen in certain situations.

HotSpot JVM has a feature called CompressedOops with which it uses 32-bit (compressed) pointers on 64-bit platforms to have smaller footprints and better performance on 64-bit platforms. 64-bit address values are stored into 32-bit pointers using an encoding and are retrieved back using the corresponding decoding.

CompressedOops implementation tries to allocate Java Heap using different strategies based on the heap size and the platform it runs on. If the heap size is less than 4Gb then it tries to allocate it into low virtual address space (below 4Gb) so that the compressed oops can be used without encoding/decoding. If it fails or heap size > 4Gb then it tries to allocate the heap below 32Gb to use zero based compressed oops. If this also fails then it switches to regular compressed oops with narrow oop base.

The heap base where the Java Heap would be based at is computed by the JVM function Universe::preferred_heap_base():

Heap base computation depends on the heap size and the HeapBaseMinAddress value for the platform we are running on. If the heap_size+HeapBaseMinAddress can fit in the first 4G address space, then heap is allocated below 4G. Then it checks if it can fit under 32G boundary otherwise java heap is allocated in the higher addresses.

In doing so, it puts a cap on the size that the native memory can grow up to, and also limits the growth of the Java Heap, and this may lead to out of memory errors for memory intensive applications. The following process map shows that the java heap is allocated just next to the native heap.

0000000100000000          8K r-x--  /sw/.es-base/sparc/pkg/jdk-1.7.0_60/bin/sparcv9/java
0000000100100000          8K rwx--  /sw/.es-base/sparc/pkg/jdk-1.7.0_60/bin/sparcv9/java
0000000100102000         56K rwx--    [ heap ]
0000000100110000       2624K rwx--    [ heap ]   <--- native Heap
00000001FB000000      24576K rw---    [ anon ]   <--- Java Heap starts here
0000000200000000    1396736K rw---    [ anon ]
0000000600000000     700416K rw---    [ anon ]

Workarounds for this situation:
1. Run with -XX:-UseCompressedOops (keeping in mind that you would lose the performance benefit that comes with enabling CompressedOops). This will instruct the JVM to run without the Compressed Oops feature and it would not try to fit the Java Heap in the first 4GB of heap.
2. Keep the CompressedOops and set the base of the Java Heap with the JVM option -XX:HeapBaseMinAddress=n to specify the address where the Java Heap should start from. If you are running out of native memory, set it to a higher address so that there is enough room available for the native mallocs, and if Java Heap is getting exhausted then set it to a lower value. And if you need java heap to be allocated beyond 4GB or 32GB then HeapBaseMinAddress should be set to a value so that HeapBaseMinAddress + heap size > 4GB or 32GB.
The default value of HeapBaseMinAddress on most of the platforms is 2GB.

Let's run a simple test program on solaris-sparc 10 and solaris-x64 11 and see where the Java Heap is placed on these platforms when using CompressedOops.

On Solaris-sparc 10 with JDK 1.7.0_67

% uname -a
SunOS svr 5.10 Generic_148888-03 sun4v sparc SUNW,Sun-Fire-T200

% java -version
java version "1.7.0_67"
Java(TM) SE Runtime Environment (build 1.7.0_67-b32)
Java HotSpot(TM) Server VM (build 24.65-b04, mixed mode)

% java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass &
[3] 22638
% -XX:InitialHeapSize=266338304 -XX:MaxHeapSize=4261412864 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+UseCompressedOops -XX:+UseParallelGC
[Global flags]
    uintx AdaptivePermSizeWeight                    = 20              {product}
    uintx GCTimeRatio                               = 99              {product}
    uintx HeapBaseMinAddress                        = 4294967296      {pd product}
    bool HeapDumpAfterFullGC                        = false           {manageable}
    Heap Parameters:
ParallelScavengeHeap [ PSYoungGen [ eden =  [0xffffffff1e800000,0xffffffff1ebf5d88,0xffffffff22a00000] , from =  [0xffffffff235000
00,0xffffffff23500000,0xffffffff24000000] , to =  [0xffffffff22a00000,0xffffffff22a00000,0xffffffff23500000]  ] PSOldGen [  [0xfffffffe75400000,0xfffffffe75400000,0xfffffffe7fc00000]  ] PSPermGen [  [0xfffffffe70400000,0xfffffffe706843a0,0xfffffffe71c00000]  ]

The default value of HeapBaseMinAddress is 4GB here and the Java Heap is allocated in the higher virtual address space.

On Solaris-x64 11 with JDK 1.7.0_67

bash-4.1$ uname -a
SunOS hsdev-15 5.11 11.0 i86pc i386 i86pc

bash-4.1$ java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass &
[1] 6049
bash-4.1$ -XX:InitialHeapSize=805015296 -XX:MaxHeapSize=12880244736 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+UseCompressedOops -XX:+UseParallelGC
[Global flags]
    uintx GCTimeRatio                               = 99              {product}
    uintx HeapBaseMinAddress                        = 268435456       {pd product}
    bool HeapDumpAfterFullGC                       = false           {manageable}
bash-4.1$ java -d64 -classpath $JAVA_HOME/lib/sa-jdi.jar sun.jvm.hotspot.CLHSDB 6049
Attaching to process 6049, please wait...
hsdb> universe
Heap Parameters:
ParallelScavengeHeap [ PSYoungGen [ eden =  [0x0000000700000000,0x00000007007ae238,0x000000070c000000] , from =  [0x000000070e0000
00,0x000000070e000000,0x0000000710000000] , to =  [0x000000070c000000,0x000000070c000000,0x000000070e000000]  ] PSOldGen [  [0x0000000500400000,0x0000000500400000,0x0000000520200000]  ] PSPermGen [  [0x00000004fb200000,0x00000004fb483380,0x00000004fc800000]  ]

bash-4.1$ pmap 6049
0000000000400000          4K r-x--  /java/bin/amd64/java
0000000000410000          4K rw---  /java/bin/amd64/java
0000000000411000       2288K rw---    [ heap ]
00000004FB200000      22528K rw---    [ anon ]
0000000500400000     522240K rw---    [ anon ]
0000000700000000     262144K rw---    [ anon ]

Here, the default value of HeapBaseMinAddress is 256MB and the Java Heap is allocated in the 32G address space.

On Solaris-x64 11 with JDK 1.8.0_20

bash-4.1$ java -version
java version "1.8.0_20"
Java(TM) SE Runtime Environment (build 1.8.0_20-b26)
Java HotSpot(TM) 64-Bit Server VM (build 25.20-b23, mixed mode)
bash-4.1$ java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass &
[1] 19069
bash-4.1$ -XX:InitialHeapSize=805015296 -XX:MaxHeapSize=12880244736 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
[Global flags]
    uintx AdaptiveSizeDecrementScaleFactor          = 4                                   {product}
    uintx GCTimeRatio                               = 99                                  {product}
    uintx HeapBaseMinAddress                        = 2147483648                          {pd product}
    bool HeapDumpAfterFullGC                        = false                               {manageable}
bash-4.1$ java -d64 -classpath $JAVA_HOME/lib/sa-jdi.jar sun.jvm.hotspot.CLHSDB 19069
Attaching to process 19069, please wait...
hsdb> universe
Heap Parameters:
ParallelScavengeHeap [ PSYoungGen [ eden =  [0x00000006c0200000,0x00000006c190a4d8,0x00000006cc200000] , from =  [0x00000006ce2000
00,0x00000006ce200000,0x00000006d0200000] , to =  [0x00000006cc200000,0x00000006cc200000,0x00000006ce200000]  ] PSOldGen [  [0x00000004c0400000,0x00000004c0400000,0x00000004e0400000]  ]  ]

bash-4.1$ pmap 19069
19069:  java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass
0000000000411000       3696K rw---    [ heap ]
00000004C0400000     524288K rw---    [ anon ]
00000006C0200000     262144K rw---    [ anon ]
00000007C0000000        512K rw---    [ anon ]

Here, HeapBaseMinAddress is 2GB by default and heap is allocated in the first 32GB address space.

The default value of HeapBaseMinAddress for Solaris-x64 systems in jdk1.7.0_xx is 256M. It has been changed to 2G in jdk8 with the following bug fix: https://bugs.openjdk.java.net/browse/JDK-8013938. 

Wednesday Mar 19, 2014

About G1 Garbage Collector, Permanent Generation and Metaspace

We received some questions around the G1 garbage collector and the use of Permanent Generation with it. There seems to be some confusion that the Hotspot JVM does not use permanent generation when G1 is used as the garbage collector. Here’s some clarification:

JDK 7: PermGen

Permanent Generation still exists in JDK 7 and its updates, and is used by all the garbage collectors. In JDK7, the effort to remove the permanent generation was started and some parts of the data residing in the permanent generation were moved to either the Java Heap or to the native heap. Permanent generation was not completely removed and it still exists in JDK 7 and its updates. Here's the list of things that were moved out of the permanent generation in JDK7:

  • Symbols were moved to the native heap

  • Interned strings were moved to the Java Heap

  • Class statics were moved to the Java Heap

JDK7: G1 and PermGen

With G1 collector, PermGen is collected only at a Full GC which is a stop-the-world (STW) GC. If G1 is running optimally then it does not do Full GCs. G1 invokes the Full GCs only when the PermGen is full or when the application does allocations faster than G1 can concurrently collect garbage.

With CMS garbage collector, we can use option -XX:+CMSClassUnloadingEnabled to collect PermGen space in the CMS concurrent cycle. There is no equivalent option for G1. G1 only collects PermGen during the Full stop-the-world GCs.

We can use options PermSize and MaxPermSize to tune the PermGen space size according to the application needs.

JDK8: PermGen

Permanent generation has been completely removed in JDK 8. This work has been done under the bug https://bugs.openjdk.java.net/browse/JDK-6964458. Options PermSize and MaxPermSize have also been removed in JDK 8.

Email to openjdk alias regarding the PermGen elimination project: http://mail.openjdk.java.net/pipermail/hotspot-dev/2012-September/006679.html

JDK8: Metaspace

In JDK 8, classes metadata is now stored in the native heap and this space is called Metaspace. There are some new flags added for Metaspace in JDK 8:

  • -XX:MetaspaceSize=<NNN> where <NNN> is the initial amount of space(the initial high-water-mark) allocated for class metadata (in bytes) that may induce a garbage collection to unload classes. The amount is approximate. After the high-water-mark is first reached, the next high-water-mark is managed by the garbage collector
  • -XX:MaxMetaspaceSize=<NNN> where <NNN> is the maximum amount of space to be allocated for class metadata (in bytes). This flag can be used to limit the amount of space allocated for class metadata. This value is approximate. By default there is no limit set.
  • -XX:MinMetaspaceFreeRatio=<NNN> where <NNN> is the minimum percentage of class metadata capacity free after a GC to avoid an increase in the amount of space (high-water-mark) allocated for class metadata that will induce a garbage collection.
  • -XX:MaxMetaspaceFreeRatio=<NNN> where <NNN> is the maximum percentage of class metadata capacity free after a GC to avoid a reduction in the amount of space (high-water-mark) allocated for class metadata that will induce a garbage collection.

By default class metadata allocation is only limited by the amount of available native memory. We can use the new option MaxMetaspaceSize to limit the amount of native memory used for the class metadata. It is analogous to MaxPermSize. A garbage collection is induced to collect the dead classloaders and classes when the class metadata usage reaches MetaspaceSize (12Mbytes on the 32bit client VM and 16Mbytes on the 32bit server VM with larger sizes on the 64bit VMs). Set MetaspaceSize to a higher value to delay the induced garbage collections. After an induced garbage collection, the class metadata usage needed to induce the next garbage collection may be increased.

Saturday Jan 04, 2014

UseLargePages on Linux

There is a JVM option UseLargePages (introduced in JDK 5.0u5) that can be used to request large memory pages from the system if large pages memory is supported by the system. The goal of the large page support is to optimize processor Translation-Lookaside Buffers and hence increase performance.

Recently we saw few instances of HotSpot crashes with JDK7 on the Linux platform when using the large memory pages.

8013057: assert(_needs_gc || SafepointSynchronize::is_at_safepoint()) failed: only read at safepoint

8007074: SIGSEGV at ParMarkBitMap::verify_clear()

Cause: The cause of these crashes is the way mmap works on the Linux platform. If the large page support is enabled on the system, commit_memory() implementation of HotSpot on Linux platform tries to commit the earlier reserved memory with 'mmap' call using the large pages. If there are not enough number of large pages available, the mmap call fails releasing the reserved memory, allowing the same memory region to be used for other allocations. This causes the same memory region to be used for different purposes and leads to unexpected behaviors.

Symptoms: With the above mentioned issue, we may see crashes with stack traces something like this:
 V  [libjvm.so+0x759a1a]  ParMarkBitMap::mark_obj(HeapWord*, unsigned long)+0x7a
 V  [libjvm.so+0x7a116e]  PSParallelCompact::MarkAndPushClosure::do_oop(oopDesc**)+0xce
 V  [libjvm.so+0x485197]  frame::oops_interpreted_do(OopClosure*, RegisterMap const*, bool)+0xe7
 V  [libjvm.so+0x863a4a]  JavaThread::oops_do(OopClosure*, CodeBlobClosure*)+0x15a
 V  [libjvm.so+0x77c97e]  ThreadRootsMarkingTask::do_it(GCTaskManager*, unsigned int)+0xae
 V  [libjvm.so+0x4b7ec0]  GCTaskThread::run()+0x130
 V  [libjvm.so+0x748f90]  java_start(Thread*)+0x100

Here the crash happens while writting to an address 0x00007f2cf656eef0 in the mapped region of ParMarkBitMap. And that memory belongs to the rt.jar (from hs_err log file):
7f2cf6419000-7f2cf65d7000 r--s 039dd000 00:31 106601532                  /jdk/jdk1.7.0_21/jre/lib/rt.jar

Due to this bug, the same memory region got mapped for two different allocations and caused this crash.


8013057 strengthened the error handling of mmap failures on Linux platform and also added some diagnostic information for these failures. It is fixed in 7u40.

8007074 fixes the reserved memory mapping loss issue when using the large pages on the Linux platform. Details on this fix: http://mail.openjdk.java.net/pipermail/hotspot-dev/2013-July/010117.html. It is fixed in JDK 8 and will also be included into 7u60, scheduled to be released in May 2014.


1. Disable the use of large pages with JVM option -XX:-UseLargePages.

2. Increase the number of large pages available on the system. By having the sufficient number of large pages on the system, we can reduce the risk of memory commit failures and thus reduce the chances of hitting the large pages issue. Please see the details on how to configure the number of large pages here:

Other related fixes:

8026887: Make issues due to failed large pages allocations easier to debug

With the fix of 8013057, diagnostic information for the memory commit failures was added. It printed the error messages something like this:
os::commit_memory(0x00000006b1600000, 352321536, 2097152, 0) failed;
error='Cannot allocate memory' (errno=12)

With this fix of 8026887, this error message has been modified to suggest that the memory commit failed due to the lack of large pages, and it now looks like the following:
os::commit_memory(0x00000006b1600000, 352321536, 2097152, 0) failed;
error='Cannot allocate large pages, falling back to small pages' (errno=12)

This change has been integrated into 7u51.

The fix for 8007074 will be available in 7u60 and could not be included into 7u51, so this change (JDK-8026887) makes the error messages printed for the large pages related commit memory failures more informative. If we see these messages in the JVM logs that indicates that we have the risk of hitting the unexpected behaviors due to the bug 8007074.

8024838: Significant slowdown due to transparent huge pages

With the fix of 8007074, significant performance degradation was detected. This regression has been fixed with JDK-8024838 in JDK 8 and will also be included in JDK 7u60.

Wednesday Jul 31, 2013

Troubleshooting Long GC Pauses

Low pause times during the application run is the most important goal for many enterprise applications, especially for the transaction-based systems where long latencies can result in the transaction time-outs. For systems running on the Java Virtual Machines, garbage collections can sometimes be the cause of the long pauses.

In this post I am going to describe different scenarios where we can encounter long GC pauses and how we can diagnose and troubleshoot these GC pauses.


Following are the different situations that can cause long GC pauses during the application run.

1. Fragmentation in the heap

Fragmentation in the Java Heap can cause GCs to occur more frequently and also sometimes causing long pauses in the GCs. This is more probable in the case of Concurrent Mark Sweep collector, also known as CMS, where the tenured generation space is not compacted with the concurrent collections.

In case of the CMS, due to fragmentation in the tenured generation space, the young generation collections can face promotion failures and thus triggering 'Concurrent Mode Failure' collections that are stop-the-world Full GCs, and Full GCs take a long time to finish as compared to the concurrent collection pauses.

Due to the fragmentation, the direct allocations in the tenured generation may fail even when there is lot of free space available and thus causing Full GCs. Fragmentation can also cause frequent allocation failures and thus triggering frequent Full GCs that increase the overall time the application is paused for.

The following logs collected with the CMS collector show that the fragmentation in the CMS generation space is very high, that leads to the promotion failure during a young generation ParNew collection and then a 'concurrent mode failure'. A Full GC is done in the event of 'concurrent mode failure' that takes a very long time, 17.1365396 seconds to finish.

{Heap before GC invocations=7430 (full 24):
par new generation total 134400K, used 121348K [0x53000000, 0x5c600000, 0x5c600000)
eden space 115200K, 99% used [0x53000000, 0x5a07e738, 0x5a080000)
from space 19200K, 32% used [0x5a080000, 0x5a682cc0, 0x5b340000)
to space 19200K, 0% used [0x5b340000, 0x5b340000, 0x5c600000)
concurrent mark-sweep generation total 2099200K, used 1694466K [0x5c600000, 0xdc800000, 0xdc800000)
concurrent-mark-sweep perm gen total 409600K, used 186942K [0xdc800000, 0xf5800000, 0xfbc00000)
10628.167: [GC Before GC:
Statistics for BinaryTreeDictionary:
Total Free Space: 103224160
Max Chunk Size: 5486
Number of Blocks: 57345
Av. Block Size: 1800
Tree Height: 36
Statistics for IndexedFreeLists:
Total Free Space: 371324
Max Chunk Size: 254
Number of Blocks: 8591 <---- High fragmentation
Av. Block Size: 43
free=103595484 frag=1.0000 <---- High fragmentation
Before GC:
Statistics for BinaryTreeDictionary:
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
Tree Height: 0
Statistics for IndexedFreeLists:
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=0 frag=0.0000
10628.168: [ParNew (promotion failed)
Desired survivor size 9830400 bytes, new threshold 1 (max 1)
- age 1: 4770440 bytes, 4770440 total
: 121348K->122157K(134400K), 0.4263254 secs]10628,594: [CMS10630.887: [CMS-concurrent-mark: 7.286/8.682 secs] [Times: user=14.81 sys=0.34, real=8.68 secs] (concurrent mode failure): 1698044K->625427K(2099200K), 17.1365396 secs] 1815815K->625427K(2233600K), [CMS Perm : 186942K->180711K(409600K)]After GC:
Statistics for BinaryTreeDictionary:
Total Free Space: 377269492
Max Chunk Size: 377269492
Number of Blocks: 1
Av. Block Size: 377269492
Tree Height: 1
Statistics for IndexedFreeLists:
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=377269492 frag=0.0000
After GC:
Statistics for BinaryTreeDictionary:
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
Tree Height: 0
Statistics for IndexedFreeLists:
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=0 frag=0.0000
, 17.5645589 secs] [Times: user=17.82 sys=0.06, real=17.57 secs]
Heap after GC invocations=7431 (full 25):
par new generation total 134400K, used 0K [0x53000000, 0x5c600000, 0x5c600000)
eden space 115200K, 0% used [0x53000000, 0x53000000, 0x5a080000)
from space 19200K, 0% used [0x5b340000, 0x5b340000, 0x5c600000)
to space 19200K, 0% used [0x5a080000, 0x5a080000, 0x5b340000)
concurrent mark-sweep generation total 2099200K, used 625427K [0x5c600000, 0xdc800000, 0xdc800000)
concurrent-mark-sweep perm gen total 409600K, used 180711K [0xdc800000, 0xf5800000, 0xfbc00000)
Total time for which application threads were stopped: 17.5730653 seconds

2. Other OS activities happening at the time of GC

Sometimes the OS activities such as the swap space or networking activity happening at the time when GC is taking place can make the GC pauses last much longer. These pauses can be of the order of few seconds to some minutes.

If your system is configured to use swap space, Operating System may move inactive pages of memory of the JVM process to the swap space, to free up memory for the currently active process which may be the same process or a different process on the system. Swapping is very expensive as it requires disk accesses which are much slower as compared to the physical memory access. So, if during a garbage collection the system needs to perform swapping, the GC would seem to run for a very long time.

Following is the log of a young generation collection that lasts for 29.47 seconds.

{Heap before GC invocations=132 (full 0):
par new generation total 2696384K, used 2696384K [0xfffffffc20010000, 0xfffffffce0010000, 0xfffffffce0010000)
eden space 2247040K, 100% used [0xfffffffc20010000, 0xfffffffca9270000, 0xfffffffca9270000)
from space 449344K, 100% used [0xfffffffca9270000, 0xfffffffcc4940000, 0xfffffffcc4940000)
to space 449344K, 0% used [0xfffffffcc4940000, 0xfffffffcc4940000, 0xfffffffce0010000)
concurrent mark-sweep generation total 9437184K, used 1860619K [0xfffffffce0010000, 0xffffffff20010000, 0xffffffff20010000)
concurrent-mark-sweep perm gen total 1310720K, used 511451K [0xffffffff20010000, 0xffffffff70010000, 0xffffffff70010000)
2013-07-17T03:58:06.601-0700: 51522.120: [GC Before GC: : 2696384K->449344K(2696384K), 29.4779282 secs] 4557003K->2326821K(12133568K) ,29.4795222 secs] [Times: user=915.56 sys=6.35, real=29.48 secs]

Corresponding 'vmstat' output at 03:58:

kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr s0 s1 s2 s3 in sy cs us sy id
20130717_035806 0 0 0 77611960 94847600 55 266 0 0 0 0 0 0 0 0 0 3041 2644 2431 44 8 48
20130717_035815 0 0 0 76968296 94828816 79 324 0 18 18 0 0 0 0 1 0 3009 3642 2519 59 13 28
20130717_035831 1 0 0 77316456 94816000 389 2848 0 7 7 0 0 0 0 2 0 40062 78231 61451 42 6 53
20130717_035841 2 0 0 77577552 94798520 115 591 0 13 13 0 0 13 12 1 0 4991 8104 5413 2 0 98

This minor GC takes around 29 secs to complete. The corresponding vmstat output shows that the available swap space drops down by ~600mb during this period. That means during this garbage collection some pages from the RAM were moved out to the swap space, not necessarily by the same process running on the system.

From the above, it is clear that the physical memory available on the system is not enough for all the processes running on the system. The way to resolve this is to run fewer processes or if possible, add more RAM to increase the physical memory of the system. In the case above, the specified maximum tenured generation size is set as 9G and out of that only 1.8G is occupied. So it makes sense to reduce the heap size to lower the memory pressure on the physical memory so as to avoid or minimize the swapping activity.

Apart from swapping, we should monitor if there is any i/o or network activity happening during the long GC pauses. These can be monitored using iostat and netstat tools. It is also helpful to see the CPU statistics with the mpstat tool to figure out if enough CPU resources were available during the GC pauses.

3. Insufficient heap size

If the application footprint is larger than the maximum heap space that we have specified for the JVM, it results in frequent collections. Due to the insufficient heap space, the allocation requests fail and the JVM needs to invoke garbage collections in an attempt to reclaim space for the allocations. But since it cannot claim much space with each collection, subsequent allocation failures result in more GC invocations.

These frequent Full GCs cause long pauses in the application run. For example, in the following case, the permanent generation is almost full and the allocation attempts into the permanent generation are failing, triggering the Full GCs.

166687.013: [Full GC [PSYoungGen: 126501K->0K(922048K)] [PSOldGen: 2063794K->1598637K(2097152K)] 2190295K->1598637K(3019200K) [PSPermGen: 165840K->164249K(166016K)], 6.8204928 secs] [Times: user=6.80 sys=0.02, real=6.81 secs]
166699.015: [Full GC [PSYoungGen: 125518K->0K(922048K)] [PSOldGen: 1763798K->1583621K(2097152K)] 1889316K->1583621K(3019200K) [PSPermGen: 165868K->164849K(166016K)], 4.8204928 secs] [Times: user=4.80 sys=0.02, real=4.81 secs]

Similarly, the frequent Full GCs can occur if there is insufficient space in the tenured generation for the allocations or promotions.

The solution for these long pauses is to identify the average footprint of the application and then specify the heap size accordingly.

4. Bug in the JVM

Sometimes these long pauses could be due to a bug in the JVM. For example, due to the following bugs in the JVM, Java applications may face long GC pauses.

  • 6459113: CMS+ParNew: wildly different ParNew pause times depending on heap shape caused by allocation spread
    • fixed in JDK 6u1 and 7
  • 6572569: CMS: consistently skewed work distribution indicated in (long) re-mark pauses
    • fixed in JDK 6u4 and 7
  • 6631166: CMS: better heuristics when combatting fragmentation
    • fixed in JDK 6u21 and 7
  • 6999988: CMS: Increased fragmentation leading to promotion failure after CR#6631166 got implemented
    • fixed in JDK 6u25 and 7
  • 6683623: G1: use logarithmic BOT code such as used by other collectors
    • fixed in JDK 6u14 and 7
  • 6976350: G1: deal with fragmentation while copying objects during GC
    • fixed in JDK 8

If you are running with a JVM version affected with these bugs, please upgrade to the version where these bugs are fixed.

5. Explicit System GCs

Check if there are any explicit System GCs happening. Requests to invoke these System GCs which are stop-the-world Full GCs could be coming from the System.gc() calls from some class in the application or from a some third party module. These explicit System GCs too can cause very long pauses.

164638.058: [Full GC (System) [PSYoungGen: 22789K->0K(992448K)] [PSOldGen: 1645508K->1666990K(2097152K)] 1668298K->1666990K(3089600K) [PSPermGen: 164914K->164914K(166720K)], 5.7499132 secs] [Times: user=5.69 sys=0.06, real=5.75 secs]

If you are using RMI and are observing explicit Full GCs on a regular interval, then these are coming from the RMI implementation that triggers System.gc() on a regular interval. This interval can be configured using the following system properties:


The default value for these properties in JDK 1.4.2 and 5.0 is 60000 milliseconds, and 3600000 milliseconds in JDK 6 and later releases.

If you want to disable the explicit Full GCs invoked using System.gc(), run the application with -XX:+DisableExplicitGC JVM option.

How to approach the problem

1. Collect GC logs with -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps and -XX:+PrintGCApplicationStoppedTime. In case of the CMS collector, add option -XX:PrintFLSStatistics=2 as well.

The GC logs can give us details on the nature and the frequency of the GC pauses i.e. they can provide answers to the questions like - are the long GC pauses occurring during young collections or old collections, and how frequently those collections are encountering long pauses.

2. Monitor the overall health of the system using OS tools like vmstat, iostat, netstat and mpstat etc. on Solaris and Linux platforms, and tools like Process Monitor and Task Manager on the Windows operating system.

3. Use GCHisto tool to visually analyze the GC Logs and figure out which GCs are taking long time and if there is a pattern in the occurrence of these collections.

4. Try to see from the GC logs if there are any signs of fragmentation in the Java Heap space.

5. Monitor if the specified Heap size is enough to contain the footprint of the application.

6. Check if you are running with a JVM that has a known bug related to the long GC pauses and then upgrade if that bug is fixed in a later version.

Monday Jun 18, 2012

Understanding G1 GC Logs

The purpose of this post is to explain the meaning of GC logs generated with some tracing and diagnostic options for G1 GC. We will take a look at the output generated with PrintGCDetails which is a product flag and provides the most detailed level of information. Along with that, we will also look at the output of two diagnostic flags that get enabled with -XX:+UnlockDiagnosticVMOptions option - G1PrintRegionLivenessInfo that prints the occupancy and the amount of space used by live objects in each region at the end of the marking cycle and G1PrintHeapRegions that provides detailed information on the heap regions being allocated and reclaimed.

We will be looking at the logs generated with JDK 1.7.0_04 using these options.

Option -XX:+PrintGCDetails

Here's a sample log of G1 collection generated with PrintGCDetails.

0.522: [GC pause (young), 0.15877971 secs]
   [Parallel Time: 157.1 ms]
      [GC Worker Start (ms):  522.1  522.2  522.2  522.2
       Avg: 522.2, Min: 522.1, Max: 522.2, Diff:   0.1]
      [Ext Root Scanning (ms):  1.6  1.5  1.6  1.9
       Avg:   1.7, Min:   1.5, Max:   1.9, Diff:   0.4]
      [Update RS (ms):  38.7  38.8  50.6  37.3
       Avg:  41.3, Min:  37.3, Max:  50.6, Diff:  13.3]
         [Processed Buffers : 2 2 3 2
          Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]
      [Scan RS (ms):  9.9  9.7  0.0  9.7
       Avg:   7.3, Min:   0.0, Max:   9.9, Diff:   9.9]
      [Object Copy (ms):  106.7  106.8  104.6  107.9
       Avg: 106.5, Min: 104.6, Max: 107.9, Diff:   3.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1 4 4 6
          Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5]
      [GC Worker End (ms):  679.1  679.1  679.1  679.1
       Avg: 679.1, Min: 679.1, Max: 679.1, Diff:   0.1]
      [GC Worker (ms):  156.9  157.0  156.9  156.9
       Avg: 156.9, Min: 156.9, Max: 157.0, Diff:   0.1]
      [GC Worker Other (ms):  0.3  0.3  0.3  0.3
       Avg:   0.3, Min:   0.3, Max:   0.3, Diff:   0.0]
   [Clear CT:   0.1 ms]
   [Other:   1.5 ms]
      [Choose CSet:   0.0 ms]
      [Ref Proc:   0.3 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   0.3 ms]
   [Eden: 12M(12M)->0B(10M) Survivors: 0B->2048K Heap: 13M(64M)->9739K(64M)]
 [Times: user=0.59 sys=0.02, real=0.16 secs]

This is the typical log of an Evacuation Pause (G1 collection) in which live objects are copied from one set of regions (young OR young+old) to another set. It is a stop-the-world activity and all the application threads are stopped at a safepoint during this time.

This pause is made up of several sub-tasks indicated by the indentation in the log entries. Here's is the top most line that gets printed for the Evacuation Pause.

0.522: [GC pause (young), 0.15877971 secs]

This is the highest level information telling us that it is an Evacuation Pause that started at 0.522 secs from the start of the process, in which all the regions being evacuated are Young i.e. Eden and Survivor regions. This collection took 0.15877971 secs to finish.

Evacuation Pauses can be mixed as well. In which case the set of regions selected include all of the young regions as well as some old regions.

1.730: [GC pause (mixed), 0.32714353 secs]

Let's take a look at all the sub-tasks performed in this Evacuation Pause.

[Parallel Time: 157.1 ms]

Parallel Time is the total elapsed time spent by all the parallel GC worker threads. The following lines correspond to the parallel tasks performed by these worker threads in this total parallel time, which in this case is 157.1 ms.

[GC Worker Start (ms): 522.1 522.2 522.2 522.2
Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1]

The first line tells us the start time of each of the worker thread in milliseconds. The start times are ordered with respect to the worker thread ids – thread 0 started at 522.1ms and thread 1 started at 522.2ms from the start of the process. The second line tells the Avg, Min, Max and Diff of the start times of all of the worker threads.

[Ext Root Scanning (ms): 1.6 1.5 1.6 1.9
Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4]

This gives us the time spent by each worker thread scanning the roots (globals, registers, thread stacks and VM data structures). Here, thread 0 took 1.6ms to perform the root scanning task and thread 1 took 1.5 ms. The second line clearly shows the Avg, Min, Max and Diff of the times spent by all the worker threads.

[Update RS (ms): 38.7 38.8 50.6 37.3
Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3]

Update RS gives us the time each thread spent in updating the Remembered Sets. Remembered Sets are the data structures that keep track of the references that point into a heap region. Mutator threads keep changing the object graph and thus the references that point into a particular region. We keep track of these changes in buffers called Update Buffers. The Update RS sub-task processes the update buffers that were not able to be processed concurrently, and updates the corresponding remembered sets of all regions.

[Processed Buffers : 2 2 3 2
Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]

This tells us the number of Update Buffers (mentioned above) processed by each worker thread.

[Scan RS (ms): 9.9 9.7 0.0 9.7
Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9]

These are the times each worker thread had spent in scanning the Remembered Sets. Remembered Set of a region contains cards that correspond to the references pointing into that region. This phase scans those cards looking for the references pointing into all the regions of the collection set.

[Object Copy (ms): 106.7 106.8 104.6 107.9
Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3]

These are the times spent by each worker thread copying live objects from the regions in the Collection Set to the other regions.

[Termination (ms): 0.0 0.0 0.0 0.0
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]

Termination time is the time spent by the worker thread offering to terminate. But before terminating, it checks the work queues of other threads and if there are still object references in other work queues, it tries to steal object references, and if it succeeds in stealing a reference, it processes that and offers to terminate again.

[Termination Attempts : 1 4 4 6
Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5]

This gives the number of times each thread has offered to terminate.

[GC Worker End (ms): 679.1 679.1 679.1 679.1
Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1]

These are the times in milliseconds at which each worker thread stopped.

[GC Worker (ms): 156.9 157.0 156.9 156.9
Avg: 156.9, Min: 156.9, Max: 157.0, Diff: 0.1]

These are the total lifetimes of each worker thread.

[GC Worker Other (ms): 0.3 0.3 0.3 0.3
Avg: 0.3, Min: 0.3, Max: 0.3, Diff: 0.0]

These are the times that each worker thread spent in performing some other tasks that we have not accounted above for the total Parallel Time.

[Clear CT: 0.1 ms]

This is the time spent in clearing the Card Table. This task is performed in serial mode.

[Other: 1.5 ms]

Time spent in the some other tasks listed below. The following sub-tasks (which individually may be parallelized) are performed serially.

[Choose CSet: 0.0 ms]

Time spent in selecting the regions for the Collection Set.

[Ref Proc: 0.3 ms]

Total time spent in processing Reference objects.

[Ref Enq: 0.0 ms]

Time spent in enqueuing references to the ReferenceQueues.

[Free CSet: 0.3 ms]

Time spent in freeing the collection set data structure.

[Eden: 12M(12M)->0B(13M) Survivors: 0B->2048K Heap: 14M(64M)->9739K(64M)]

This line gives the details on the heap size changes with the Evacuation Pause. This shows that Eden had the occupancy of 12M and its capacity was also 12M before the collection. After the collection, its occupancy got reduced to 0 since everything is evacuated/promoted from Eden during a collection, and its target size grew to 13M. The new Eden capacity of 13M is not reserved at this point. This value is the target size of the Eden. Regions are added to Eden as the demand is made and when the added regions reach to the target size, we start the next collection.

Similarly, Survivors had the occupancy of 0 bytes and it grew to 2048K after the collection. The total heap occupancy and capacity was 14M and 64M receptively before the collection and it became 9739K and 64M after the collection.

Apart from the evacuation pauses, G1 also performs concurrent-marking to build the live data information of regions.

1.416: [GC pause (young) (initial-mark), 0.62417980 secs]
2.042: [GC concurrent-root-region-scan-start]
2.067: [GC concurrent-root-region-scan-end, 0.0251507]
2.068: [GC concurrent-mark-start]
3.198: [GC concurrent-mark-reset-for-overflow]
4.053: [GC concurrent-mark-end, 1.9849672 sec]
4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
4.090: [GC concurrent-cleanup-start]
4.091: [GC concurrent-cleanup-end, 0.0002721] 

The first phase of a marking cycle is Initial Marking where all the objects directly reachable from the roots are marked and this phase is piggy-backed on a fully young Evacuation Pause.

2.042: [GC concurrent-root-region-scan-start]

This marks the start of a concurrent phase that scans the set of root-regions which are directly reachable from the survivors of the initial marking phase.

2.067: [GC concurrent-root-region-scan-end, 0.0251507]

End of the concurrent root region scan phase and it lasted for 0.0251507 seconds.

2.068: [GC concurrent-mark-start]

Start of the concurrent marking at 2.068 secs from the start of the process.

3.198: [GC concurrent-mark-reset-for-overflow]

This indicates that the global marking stack had became full and there was an overflow of the stack. Concurrent marking detected this overflow and had to reset the data structures to start the marking again.

4.053: [GC concurrent-mark-end, 1.9849672 sec]

End of the concurrent marking phase and it lasted for 1.9849672 seconds.

4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs]

This corresponds to the remark phase which is a stop-the-world phase. It completes the left over marking work (SATB buffers processing) from the previous phase. In this case, this phase took 0.0030184 secs and out of which 0.0000254 secs were spent on Reference processing.

4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs]

Cleanup phase which is again a stop-the-world phase. It goes through the marking information of all the regions, computes the live data information of each region, resets the marking data structures and sorts the regions according to their gc-efficiency. In this example, the total heap size is 138M and after the live data counting it was found that the total live data size dropped down from 117M to 106M.

4.090: [GC concurrent-cleanup-start]

This concurrent cleanup phase frees up the regions that were found to be empty (didn't contain any live data) during the previous stop-the-world phase.

4.091: [GC concurrent-cleanup-end, 0.0002721]

Concurrent cleanup phase took 0.0002721 secs to free up the empty regions.

Option -XX:G1PrintRegionLivenessInfo

Now, let's look at the output generated with the flag G1PrintRegionLivenessInfo. This is a diagnostic option and gets enabled with -XX:+UnlockDiagnosticVMOptions. G1PrintRegionLivenessInfo prints the live data information of each region during the Cleanup phase of the concurrent-marking cycle.

26.896: [GC cleanup
### PHASE Post-Marking @ 26.896
### HEAP committed: 0x02e00000-0x0fe00000 reserved: 0x02e00000-0x12e00000 region-size: 1048576

Cleanup phase of the concurrent-marking cycle started at 26.896 secs from the start of the process and this live data information is being printed after the marking phase. Committed G1 heap ranges from 0x02e00000 to 0x0fe00000 and the total G1 heap reserved by JVM is from 0x02e00000 to 0x12e00000. Each region in the G1 heap is of size 1048576 bytes.

### type address-range used prev-live next-live gc-eff
### (bytes) (bytes) (bytes) (bytes/ms)

This is the header of the output that tells us about the type of the region, address-range of the region, used space in the region, live bytes in the region with respect to the previous marking cycle, live bytes in the region with respect to the current marking cycle and the GC efficiency of that region.

### FREE 0x02e00000-0x02f00000 0 0 0 0.0

This is a Free region.

### OLD 0x02f00000-0x03000000 1048576 1038592 1038592 0.0

Old region with address-range from 0x02f00000 to 0x03000000. Total used space in the region is 1048576 bytes, live bytes as per the previous marking cycle are 1038592 and live bytes with respect to the current marking cycle are also 1038592. The GC efficiency has been computed as 0.

### EDEN 0x03400000-0x03500000 20992 20992 20992 0.0

This is an Eden region.

### HUMS 0x0ae00000-0x0af00000 1048576 1048576 1048576 0.0
### HUMC 0x0af00000-0x0b000000 1048576 1048576 1048576 0.0
### HUMC 0x0b000000-0x0b100000 1048576 1048576 1048576 0.0
### HUMC 0x0b100000-0x0b200000 1048576 1048576 1048576 0.0
### HUMC 0x0b200000-0x0b300000 1048576 1048576 1048576 0.0
### HUMC 0x0b300000-0x0b400000 1048576 1048576 1048576 0.0
### HUMC 0x0b400000-0x0b500000 1001480 1001480 1001480 0.0

These are the continuous set of regions called Humongous regions for storing a large object. HUMS (Humongous starts) marks the start of the set of humongous regions and HUMC (Humongous continues) tags the subsequent regions of the humongous regions set.

### SURV 0x09300000-0x09400000 16384 16384 16384 0.0

This is a Survivor region.

### SUMMARY capacity: 208.00 MB used: 150.16 MB / 72.19 % prev-live: 149.78 MB / 72.01 % next-live: 142.82 MB / 68.66 %

At the end, a summary is printed listing the capacity, the used space and the change in the liveness after the completion of concurrent marking. In this case, G1 heap capacity is 208MB, total used space is 150.16MB which is 72.19% of the total heap size, live data in the previous marking was 149.78MB which was 72.01% of the total heap size and the live data as per the current marking is 142.82MB which is 68.66% of the total heap size.

Option -XX:+G1PrintHeapRegions

G1PrintHeapRegions option logs the regions related events when regions are committed, allocated into or are reclaimed.


G1HR COMMIT [0x6e900000,0x6ea00000]
G1HR COMMIT [0x6ea00000,0x6eb00000]

Here, the heap is being initialized or expanded and the region (with bottom: 0x6eb00000 and end: 0x6ec00000) is being freshly committed. COMMIT events are always generated in order i.e. the next COMMIT event will always be for the uncommitted region with the lowest address.

G1HR UNCOMMIT [0x72700000,0x72800000]
G1HR UNCOMMIT [0x72600000,0x72700000]

Opposite to COMMIT. The heap got shrunk at the end of a Full GC and the regions are being uncommitted. Like COMMIT, UNCOMMIT events are also generated in order i.e. the next UNCOMMIT event will always be for the committed region with the highest address.

GC Cycle events

G1HR #StartGC 7
G1HR CSET 0x6e900000
G1HR REUSE 0x70500000
G1HR ALLOC(Old) 0x6f800000
G1HR RETIRE 0x6f800000 0x6f821b20
G1HR #EndGC 7

This shows start and end of an Evacuation pause. This event is followed by a GC counter tracking both evacuation pauses and Full GCs. Here, this is the 7th GC since the start of the process.

G1HR #StartFullGC 17
G1HR UNCOMMIT [0x6ed00000,0x6ee00000]
G1HR POST-COMPACTION(Old) 0x6e800000 0x6e854f58
G1HR #EndFullGC 17

Shows start and end of a Full GC. This event is also followed by the same GC counter as above. This is the 17th GC since the start of the process.

ALLOC events

G1HR ALLOC(Eden) 0x6e800000

The region with bottom 0x6e800000 just started being used for allocation. In this case it is an Eden region and allocated into by a mutator thread.

G1HR ALLOC(StartsH) 0x6ec00000 0x6ed00000
G1HR ALLOC(ContinuesH) 0x6ed00000 0x6e000000

Regions being used for the allocation of Humongous object. The object spans over two regions.

G1HR ALLOC(SingleH) 0x6f900000 0x6f9eb010

Single region being used for the allocation of Humongous object.

G1HR COMMIT [0x6ee00000,0x6ef00000]
G1HR COMMIT [0x6ef00000,0x6f000000]
G1HR COMMIT [0x6f000000,0x6f100000]
G1HR COMMIT [0x6f100000,0x6f200000]
G1HR ALLOC(StartsH) 0x6ee00000 0x6ef00000
G1HR ALLOC(ContinuesH) 0x6ef00000 0x6f000000
G1HR ALLOC(ContinuesH) 0x6f000000 0x6f100000
G1HR ALLOC(ContinuesH) 0x6f100000 0x6f102010

Here, Humongous object allocation request could not be satisfied by the free committed regions that existed in the heap, so the heap needed to be expanded. Thus new regions are committed and then allocated into for the Humongous object.

G1HR ALLOC(Old) 0x6f800000

Old region started being used for allocation during GC.

G1HR ALLOC(Survivor) 0x6fa00000

Region being used for copying old objects into during a GC.

Note that Eden and Humongous ALLOC events are generated outside the GC boundaries and Old and Survivor ALLOC events are generated inside the GC boundaries.

Other Events

G1HR RETIRE 0x6e800000 0x6e87bd98

Retire and stop using the region having bottom 0x6e800000 and top 0x6e87bd98 for allocation.

Note that most regions are full when they are retired and we omit those events to reduce the output volume. A region is retired when another region of the same type is allocated or we reach the start or end of a GC(depending on the region). So for Eden regions:

For example:

1. ALLOC(Eden) Foo
2. ALLOC(Eden) Bar
3. StartGC

At point 2, Foo has just been retired and it was full. At point 3, Bar was retired and it was full. If they were not full when they were retired, we will have a RETIRE event:

1. ALLOC(Eden) Foo
2. RETIRE Foo top
3. ALLOC(Eden) Bar
4. StartGC

G1HR CSET 0x6e900000

Region (bottom: 0x6e900000) is selected for the Collection Set. The region might have been selected for the collection set earlier (i.e. when it was allocated). However, we generate the CSET events for all regions in the CSet at the start of a GC to make sure there's no confusion about which regions are part of the CSet.

G1HR POST-COMPACTION(Old) 0x6e800000 0x6e839858

POST-COMPACTION event is generated for each non-empty region in the heap after a full compaction. A full compaction moves objects around, so we don't know what the resulting shape of the heap is (which regions were written to, which were emptied, etc.). To deal with this, we generate a POST-COMPACTION event for each non-empty region with its type (old/humongous) and the heap boundaries. At this point we should only have Old and Humongous regions, as we have collapsed the young generation, so we should not have eden and survivors.

POST-COMPACTION events are generated within the Full GC boundary.

G1HR CLEANUP 0x6f400000
G1HR CLEANUP 0x6f300000
G1HR CLEANUP 0x6f200000

These regions were found empty after remark phase of Concurrent Marking and are reclaimed shortly afterwards.

G1HR #StartGC 5
G1HR CSET 0x6f400000
G1HR CSET 0x6e900000
G1HR REUSE 0x6f800000

At the end of a GC we retire the old region we are allocating into. Given that its not full, we will carry on allocating into it during the next GC. This is what REUSE means. In the above case 0x6f800000 should have been the last region with an ALLOC(Old) event during the previous GC and should have been retired before the end of the previous GC.

G1HR ALLOC-FORCE(Eden) 0x6f800000

A specialization of ALLOC which indicates that we have reached the max desired number of the particular region type (in this case: Eden), but we decided to allocate one more. Currently it's only used for Eden regions when we extend the young generation because we cannot do a GC as the GC-Locker is active.

G1HR EVAC-FAILURE 0x6f800000

During a GC, we have failed to evacuate an object from the given region as the heap is full and there is no space left to copy the object. This event is generated within GC boundaries and exactly once for each region from which we failed to evacuate objects.

When Heap Regions are reclaimed ?

It is also worth mentioning when the heap regions in the G1 heap are reclaimed.

  • All regions that are in the CSet (the ones that appear in CSET events) are reclaimed at the end of a GC. The exception to that are regions with EVAC-FAILURE events.

  • All regions with CLEANUP events are reclaimed.

  • After a Full GC some regions get reclaimed (the ones from which we moved the objects out). But that is not shown explicitly, instead the non-empty regions that are left in the heap are printed out with the POST-COMPACTION events.




« September 2016