Styjun

Problem

A Glassfish instance with 60 webapps (.war's) installed occasionally burns 100-150% of a CPU core or more for many minutes while there is no significant workload to justify it.

Sometimes it gets so bad that applications stop responding and the instance will not shut down in reasonable time (> 1 hour) without a kill -9.

Environment

• Linux (CentOS) 4 core, physical hardware.




• Java 1.8u65, Oracle, Hotspot




• Glassfish 4.1.1 - About 60 WebApps (war files) installed.




• JMX reports plenty of free heap (arund 50%). Linux reports insignificant memory pressure.




• Nonessential GF tasks such as autodeploy, autorefresh, updater, are disabled.

Investigation

I can reproduce the problem on an idle system with la <= 0.3 by navigating to the Applications view in Glassfish html admin console after a fresh restart of GF with all applications except admin console disabled.

Navigating to the Applications view causes GF to open 195 loopback ssl connections. The GF admin gui source code shows that their jsf layer will make >1 https request to the GF instance (itself) for each app installed.

Using top/htop and JVM thread dumps I found that the threads with runaway cpu use were all named HandshakeCompletionNotify_Thread, and created by javax.net.SSLSocketImpl.

Many HandshakeCompletionNotify threads (>40) were hanging around and a few of them (1 to 4 on a four core instance) were always using 40% to 100% of a cpu core.

What does the code say?

The OpenJDK SSLSocketImpl source suggests that the HandshakeCompletionNotify_Thread really does not have much to do. It normally completes very quickly and ends the thread. Here's the run method from OpenJDK's JDK 8 to show the concept.

@Override
 public void run() 
 // Don't need to synchronize, as it only runs in one thread.
 for (Map.Entry<HandshakeCompletedListener,AccessControlContext>
 entry : targets) 

 final HandshakeCompletedListener l = entry.getKey();
 AccessControlContext acc = entry.getValue();
 AccessController.doPrivileged(new PrivilegedAction<Void>() 
 @Override
 public Void run() 
 l.handshakeCompleted(event);
 return null;
 
 , acc);
 
 

• We don't use a security manager, so doPrivileged should not be able to delay it significantly.




• targets is a HashSet<>, so no synchronization.




• Implementations of HandshakeCompletedListener that I have found don't seem to have any reason to block on the handshakeCompleted() method.

The HandshakeCompletionNotify_Threads appear in the thread dump in Runnable state with no stack trace. Not sure what this means. Were these threads not responding to signals? (speculation) Had they not yet called the run() method? The JDK documentation warns that some JVM's may leave frames out of stack traces. Would that explain it?

Question

1. Why would these HandshakeCompletionNotify_Threads pile up and burn cpu time?




2. How can I prevent it from happening?

Hunches (nothing solid)

• We're actually waiting for thread creation and initialization. Something is jammed there.




• They are burning time in a system call that I can't see, maybe allocating or mapping memory.




• We missed some configuration for ssl, dns, something.

Why do I care?
I did the investigation to find out if my team's software had introduced something too risky to release into production environments. Now I am sure our software does not have to be present to produce the problem.

Now the problem just bugs me and I don't want to have trouble with it at scale. There were a couple of JDK bugs reported on JDK 1.6 related to these completion notify threads, but they are logged as fixed in JDK 7 and 8. Maybe there is a remaining aspect of the JDK bug. Maybe Glassfish or Grizzly has a badly implemented HandShakeCompletionListener.