At my day job I’ve spent the better part of a month working on a nasty performance tuning problem in some software that I didn’t actually write. Without going into much detail we have a distributed application that provides cover images (a la Amazon) to the websites and other applications at various divisions with Follett. There are multiple caching layers, and heavy use of 3rd party software such as lucene and tomcat. The problem was the image query service would ocasionally take 10 times as long (or more) to service a request.
Initially I used a tool called jrat to profile the application in question to see where it was spending its time. jrat is a neat little application that uses the Byte Code Engineering Library to instrument Java class files so that they write timing information to a log file. jrat then has a visualization tool that lets you open the log and view timings for the various methods. After doing this it became clear that a large amount of time was being spent in searching the Lucene index.
So I isolated the searching component of the code and replicated the timeout behavior outside of the web container. Once I could replicate the behavior at will I was able to start turning knobs and switching switches to try to get better performance. One of the first obvious things I tried was to create one IndexSearcher object and share it across the threads. This helped a great deal and I was happy. Thinking that it was the creation of the Searchers which slowed things down I created a pool of IndexSearchers which the application drew from, and a worker thread that kept the pool full. This change also worked well outside of Tomcat; however once it ran under Tomcat I saw the same delays. The test outside of Tomcat pushed the searching much harder that our web traffic ever did…so extrapolating from one to the other wasn’t appropriate. I had fixed a problem but not the problem.
This is when depression set in…
After I had started to think clearly again I happened to have lunch with Mike who asked if JVM garbage collection could have anything to do with it. I practically slapped myself on the forehead. This is what all those articles warned me about when discussing Java and embedded software! I went back, turned on garbage collection logging and sure enough, every 10-20 seconds the JVM was spending sometimes around 2 seconds collecting a huge amount of memory. I had a little log analysis tool that told me when the response times were exceeding 2 seconds, and sure enough these popped up while the full GC was running. What objects were chewing up that amount of space?
This is when Bob suggested giving the commercial Java tuning app YourKit a try. They have a fully functional 14 day demo which I got to run under RH Fedora Core 2 in fairly short order. YourKit can talk to a host of J2EE servers including Tomcat. On startup it asks what type of server you want it to attach to. After selecting Tomcat it goes and creates a new Tomcat startup script based on the existing one. After resetarting Tomcat YourKit is able to selectively log a ton of data from the running JVM, including memory usage.
This screen alone (click on it for a more readable version) showed that a large chunk of memory was being used up by all the IndexSearcher objects that were being created. So I had been right to focus on the IndexSearcher after all, but it wasn’t that they were expensive to create, but that they resulted in a great deal of memory being used which caused the JVM to stall out while garbage collection was being done. I confirmed this by hacking the app to keep one IndexSearcher around and stress testing again, which performed nicely.
While I don’t have a solution in code yet, this whole exercise has made it clear to me how important communication is in programming. I always seem to get better results when talking to people I work with. It’s so easy to get stuck in one way of looking at a problem, and discussion has a way of dislocating my perspective, challenging my assumptions, and bringing humor into a problem. In addition good tools are worth their weight in gold. I spent far too much time guessing and testing when I could have used something like YourKit from the start. One thing that has impressed me a lot about Java are the high quality development tools that are available.