In the Session.flush method has a lost of perfomance about 50% when flush a large amout of data

Description

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.

Tks.

Environment

Linux / DB2 / version 3.2.6 and above

Activity

Show:

Fabiano Cury

April 1, 2010, 9:14 PM

Copy link to comment

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".

Strong Liu

April 2, 2010, 7:42 AM

Copy link to comment

Juca,

would you like do some pref test on this case to see if this change is worth　to　apply?

Juraci Paixão Kröhling

April 2, 2010, 10:52 AM

Copy link to comment

Sure thing. I'll add this to my list.

Juraci Paixão Kröhling

June 11, 2010, 10:28 AM

Copy link to comment

Fabiano,

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.