I love the Hibernate framework from JBoss, truly I do. The productivity that it gives me is through the roof, well once I got used to it that is. I do have to admit that this past week has greatly tested my affection for this best of breed ORM tool. During a demo I noticed that the beta server simply stopped responding. I thought to myself, “Hmmm, thats odd, I wonder what is going on.” I used my Jedi mind trick on the customers by waiving my arms in the air and speaking authoritatively like I actually knew what was going on (thankfully they bought it :P). Once I got back to my desk, I found out that the server had crashed and went down in flames. Over the next few days we constantly experienced all of the memory being gobbled up.
I scoured the net to find some sort of solution. From my research, I was fairly confident that our problem was stemming from a misconfiguration of Hibernate. I went through an entire gyration of writing code to put our server under load. Finally I was able to reproduce the problem at will. That was step one, then on to more research and delving into the very bowls of Hibernate code.
To make a long and semi-humorous story short, it had nothing to do with how Hibernate was written or “bugs” that were known issues on certain platforms. There is quite a bit of speculation that Hibernate’s usage of CGLib can leak memory. This may very well be but my problem was… are you ready for this… the logging from Hibernate! Hibernate has a very robust logging option that will show you all of the SQL that is being generated. In a few areas of the application there were a ton of queries being executed and the logging system couldn’t keep up with everything being logged. All of the Strings being logged wouldn’t get garbaged collected because the logger had a reference to them and there were millions and millions of Strings piling up in memory and **POOF** no more memory.
So if you are using Hibernate and having problems with memory, I have one quick line of XML for you to try…
<property name=”hibernate.show_sql”>false</property>
Well, Jeff, you and I have had discussions many times on the pros and cons of Hibernate. What’s funny is that I have never, ever seen the logging from any system pile up so fast that it ate up all the memory, but it could certainly happen, particularly under heavy load.
Two additional things come to mind so you don’t have to completely give up on seeing the SQL all the time:
1) Look at your memory settings on your JVM, particularly -Xmx### setting, and the the too-frequently ignored -XX:MaxPermSize=### setting that controls your PermGen space
2) Rather than completely giving up on seeing the SQL, use different log4j settings in prod than you do in development. You can have “hibernate.show_sql” off and still see the sql if you set the logger for log4j.logger.org.hibernate.SQL=DEBUG.
That’s a great hint Jeff, thanks for sharing this. It’s really coincidental that I just wrote a blog post on using 3rd-party libs and bug hunting: http://dlinsin.blogspot.com/2008/03/why-me.html
Very intresting, it puzzled my mind quite a bit.
As you state, Hibernate keeps the logging in memory, until it has time to be processed. Does this mean that, when under heavy load, the logging isn’t guaranteed to be written down? I’d thought, when a transaction is finished, all logging of the transaction would at least catch up before starting the next one.
I find it very strange that the logging isn’t guaranteed.
It isn’t that the logging isn’t guaranteed, it case of a JVM crashing because it is out of memory. When a JVM crashes, it is hard to tell what is going to be completed and what will not.
Also, it wasn’t so much Hibernate that was keeping it in memory, it was the Log4j loggers that had it queued up. Hibernate was the producer of the data being passed to Log4j. It is much like any production code, you typically don’t want to have tons of logging going on when in a production environment, certainly not at a “debug” level.