Interesting Performance Problem : The Usual Suspects?

An interesting performance problem got solved this week. One of our clients noticed dramatically bad performance in our Java servlet/jsp web-server compared to a competitor.

The usual trick to narrow these down are to take thread dumps at the time when the server looks busy. It kept showing us dumps that seemed like most of the time was spent waiting for the database to respond. A quick timing calculation showed that the database was taking a short fraction of the time. After introducing more timing stats between some large pieces of execution we managed to find a bottleneck only to see that it moved the next run - thus making us suspect Garbage Collection. Switch on -verbose:gc and there we were minor Garbage Collection Runs a full 8 and a half seconds.

The Usual Suspects are runaway streams, memory leaks, excessive object creation none of which could be caught in our JVMPI profiler. Amazingly, even after 3 days of intense debugging we knew it was GC that was leading to our problems but we could not isolate what it was that caused it!

We tried IBM JDK and its VM and we compared identical to our competitor. IBM JVM is an amazing piece of software but thats a story for another time.

None of the usual suspects seemed to be involved. We went back to commenting out pieces of the offending JSP and isolated the problem to excessive try-finally blocks in our code generation. We got rid of them and lo behold! we were as fast too!

Why would try-finally result in such high GC times in Sun JVMs? I can only suspect if GC happens when there are a lot of try finally blocks the code is unoptimized? Would love the answer to that one...