I am profiling a Grails web application with JProfiler and JConsole and am observing a phenomenon I am unable to fully understand.
The setup I am profiling is as follows:
- A Grails web application built with maven as WAR and deployed to Tomcat.
- A single Solr instance
- Tomcat with a thread pool size of 100 HTTP worker threads, BIO connector
The application calls Solr for nearly every request. There's no DB and no other backend interaction. Ehcache ist used for some caching.
I have created a set of moderate load tests that are fired against the application. I have figured out a kind of load limit for my local setup. Below that limit I make the following observations with regard to the Grails application:
- Response times < 500ms
- HTTP threads are mainly spending time with net I/O, a bit runnable and wait time and very little block time
- CPU around 70%
When I raise the load a bit beyond said limit, the picture drastically changes:
- Response times increase to a couple of seconds
- HTTP threads are mainly in blocking or runnable state, very little net I/O and wait time
- CPU seems to "jump" a lot between 40% and 80%
Now while it is totally understandable that things get slower under higher load I am very concerned about the fact that above the load limit lock contention occurs and a significant amount of time is spent blocking. I investigated the monitor history and especially found a lot of events similar to the following:
- Monitor class
org.apache.catalina.loader.WebappClassLoader - Waiting and owning thread are some HTTP worker
- Time spent blocking for the monitor is significant (around 2 seconds regularly)
- These events also occur below the load limit but they are rare and don't have such destructive impact
- Stacktraces of the owning and waiting threads are very different, below is an example.
Filtered stacktrace of the owning thread
groovy.lang.GroovyClassLoader.loadClass(java.lang.String)
Script1.$createCallSiteArray()
Script1.$getCallSiteArray()
Script1.__$swapInit()
Script1.<clinit>()
groovy.lang.Script$evaluate.callCurrent(groovy.lang.GroovyObject, java.lang.Object)
gsp_some_gsp_gsp.run()
org.codehaus.groovy.grails.web.pages.GroovyPagesTemplateRenderer.render(...)
Script1.call(java.lang.Object, java.lang.Object[ ])
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(...)
Filtered stacktrace of the waiting thread:
groovy.lang.Script$evaluate.callCurrent(groovy.lang.GroovyObject, java.lang.Object)
gsp_some_gsp_gsp.run()
org.codehaus.groovy.grails.web.pages.GroovyPagesTemplateRenderer.render(...)
Script1.call(java.lang.Object, java.lang.Object[ ])
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(...)
gsp_some_other_gsp_gsp$_run_closure2_closure5.doCall()
org.codehaus.groovy.grails.web.taglib.GroovyPageTagBody.call()
java_util_concurrent_Callable$call$53.call(java.lang.Object)
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(...)
Another observations (regardless of the load limit) is that, the total number of loaded classes is constantly increasing. (There also occurs regular class unloading, so PermGen is not an issue so far but it seems that new classes are constantly generated.)
My question is why this kind of blocking on the WebappClassLoader happens. Is this normal behaviour and the fact that above the load limit blocking threads stack up is just a sign that the machine is overloaded? Has this something to do with Groovy or Grails or Tomcat class loading? Is there something that can be done about it?
Some additional details about the system:
java version "1.7.0_51"
OpenJDK Runtime Environment (IcedTea 2.4.4) (7u51-2.4.4-0ubuntu0.12.04.2)
OpenJDK 64-Bit Server VM (build 24.45-b08, mixed mode)
Grails version 2.3.4
Groovy version 2.1.9
Ehcache 2.4.6
Tomcat version 7.0.26
Ubuntu 12.04
curl-loader for load tests
