HotSpot Bug in JVM1.7
Recently, I had to cope with a very peculiar production problem, which proved quite hard to tackle down and very easy to fix, as most of problems of this nature. The problem was manifesting sometimes on only one of our Java servers, and was leading to a sudden global slowdown of the whole JVM by at least 5-10 times. In the beginning, I was trying to find the needle in the haystack of concurrency, object creation, leaks e.t.c. However, there was nothing obvious in these places although the problem was looking like some kind of memory aggregation situation or deadlock situation, from which the JVM was never recovering.
Days and months of investigation through recent and older logs, gc and heap analysis and massive optimizations did not seem to help and the devil was lurking anytime at our door, ready to hit with his unexpected visit. Only a restart would eventually help.
One day, one of our brilliant engineers said that we should perhaps look into the internals of the JVM safepoints. As such, we activated at a first step the logging of these peculiar and strange safepoints through the addition of the
-XX:+TraceSafepointCleanupTime -XX:+PrintSafepointStatistics
parameters. Have you ever had to look at this printout? Chances are that you didn't have to. For those of you though that have taken a glimpse into this hell of logging, you know what kind of pain it can cause. Even if somebody neglects the fact that there is no possibility to direct that logging to a special file and it HAS to be logged in the stdout file of your application, you can say that the printout could have been a bit better after 20 years of Java development. A safepoint log line consists of a timestamp - in seconds after the process startup - and an event. Even with that logging, we were not able to notice something useful and then we moved to the next step of activating the compilation trace of the JIT compiler of HotSpot. This polluted our stdout log file even more and not only that but the JIT events contain the timestamp not in the form of seconds but in the form of milliseconds since the process's startup time(-XX:+PrintCompilation parameter).
However, we managed to track down a few hundreds of logs around the time of the problem appearing. Then we observed a very strange event saying something like this HandleFullCodeCache. More worrying was the fact that after that event, JIT seemed to only remove compiled code and turn already compiled methods into zombies. There was not a single optimization since then. As such, I decided to create a histogram with aggregations of 1 minute between optimization, deoptimizations and zombie events taken out from the JIT log. The result is depicted in the following picture.
The first orange spike in the histogram shows the initial optimizations done by JIT. These are good. In the beginning, a lot of optimizations, followed by zombies, are done until JIT reaches a certain mature state, where it decides which parts of the code are worthwhile staying optimized and which not. However, just before the middle of the day, we have two huge spikes, one for deoptimizations and one for zombies. Since the results are aggregated per second, we can say with certainty that these deoptimizations happened very suddenly. This was actually the time, at which we got the HandleFullCacheEvent. After that, no orange spikes can be seen, which would denote optimizations. In simple words that means that JVM runs completely without JIT, so it runs only in the old interpreted mode, which is of course very slow.
Googling for possible causes, we landed over a notorious bug of the JDK, reported here http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8006952. It seems that JIT contains a bug, with which any further optimization is irreparably avoided once the code cache gets full. I managed to reproduce the problem on a simple test application by setting the code cache to a really small value, such that it is easy to get the event. By default, the cache is set to 96MB (as of JRE 1.7). After doubling the code cache (this can be done by setting the parameter -XX:ReservedCodeCacheSize), we never got into the problem again and the JIT histogram started looking like the following picture.
Note: The bug is fixed in newer versions of Java. For those of you that still work with 1.7 though, remember that you can get into real trouble with this very strange and hard to find bug.