When the flush method is called this method call the onFlush method of class DefaultFlushEventListener and then the method flushEverythingToExecutions(event).
This method (flushEverythingToExecutions) call many times (loop) the method log.isDebugEnabled().
This cause a big overhead in this method.
I suggest you to put an attribute in the method flushEverythingToExecutions(flushEverythingToExecutions(FlushEvent event, Boolean isDebugEnable) and verify this attribute before the loop for.
Attached the print screen of profiling that help me to detect this issue.
Linux / DB2 / version 3.2.6 and above
In a nutshell: notice that over 3% of the TOTAL EXECUTION TIME of this application is wasted by Hibernate calling method isDebugEnabled (although debug is disabled) inside a loop over 2 million times. This overhead could be easily avoided simply calling this method just once, outside the loop, and then assigning it to a local variable defined as "final boolean isDebugEnabled".
would you like do some pref test on this case to see if this change is worth to apply?
Sure thing. I'll add this to my list.
Would you please provide more details and/or a code that depicts this? I wasn't able to find this bottleneck in any of my tests, so, maybe I don't have the same environment as you. I have Fedora 13, Sun HotSpot Server JVM 1.6.22 32-bit, Log4J, local mysql database, Hibernate 3.3.2.GA. You seem to have Linux, DB2 and Hibernate 3.2 (tested in higher versions too). Which VM are you using (IBM? Sun? 32 x 64 bit?) and with which parameters? It seems you are using logback logging facility. Do you see the same result with Log4J?
Also, it's very strange that isDebugEnabled would cause such a performance hit, as it's supposed to be a very inexpensive operation. I didn't checked that, but I think that the HotSpot VM would also take care of optimizing this call.