Working with an app that requires live fast response times we experienced some random pauses in the execution. Normally a server request would take about 100 milliseconds but every now and then a request took considerably longer and logging showed that it was not always the same method calls that took up to 2 seconds and sometimes longer.

Suspicion began to fall on the jvm performance (Suns Jvm for Java 1.4.2) and some logging parameters was added to one of the servers in a production cluster.

java -Xloggc:gc.log -XX:+PrintGCDetails

Looking at the gc.log in a graphical tool showed this picture:

Notice that the jvm has over 700MB memory but only uses around 200MB because a full garbage collection is run every minute, and that most pauses is between 0.6 and 0.9 seconds. This interrupts the execution on the server creating the unwanted pauses.

Investigating the subtle workings of garbage collection revealed that remote method invocation (RMI – when a remote client calls an object on the server) has a role to play in how often the server-side jvm performs a full garbage collection. By default the RMI calls System.garbageCollect() every minute, which can give the long pauses.

Increasing the interval between full garbage collections to 30 minutes (here both for client and server) helped to reduce pause considerably.

java ... -Dsun.rmi.dgc.client.gcInterval=1800000 
-Dsun.rmi.dgc.server.gcInterval=1800000

One thing to note is that increasing the memory will only make the pauses longer because more garbage would be able to fill up until a full garbage collection needs to be performed. So putting lots of memory blocks in your box and boosting the jvm with more memory does not necessary help the user experience. Instead you have to suit to the actual needs of your application, for example based on how many objects are cached.

Further more on a multiprocessor server, you can benefit from enabling a concurrent garbage collector that runs in a separate thread, so the main threads are not interrupted.

java ... -XX:+UseConcMarkSweepGC

With this collector you get lots of small garbage collections in the background and practically no long pauses in the application. Notice that here we also set the initial size of the jvm to 256MB letting the jvm itself determine how much memory is needed.

So remember to dive into your jvm when performance issues arises.

Want to read more:

http://www.tagtraum.com/gcviewer.html

http://developers.sun.com/mobility/midp/articles/garbagecollection2/index.html

More general on jvm options

http://java.sun.com/javase/technologies/hotspot/vmoptions.jsp

 

By Jesper Thaning