Bug 1094756 - [QE] (6.2.3) HHH-9170 HHH-9174 ORM Performance regression
Summary: [QE] (6.2.3) HHH-9170 HHH-9174 ORM Performance regression
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: Hibernate
Version: 6.2.3
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: CR4
: EAP 6.2.3
Assignee: Brett Meyer
QA Contact: Martin Simka
Russell Dickenson
URL:
Whiteboard:
Depends On: 1096043
Blocks: eap62-cp03-blockers 1096304
TreeView+ depends on / blocked
 
Reported: 2014-05-06 12:22 UTC by Pavel Slavicek
Modified: 2015-09-01 04:01 UTC (History)
12 users (show)

Fixed In Version:
Doc Type: Known Issue
Doc Text:
A regression that can cause performance degradation is present in this release of JBoss EAP 6. It has been traced to the `Statement#getWarnings` method (which was negatively impacted by changes made to resolve an earlier memory leak caused by a bug in the Sybase JDBC drivers). To address the performance issues, new code has been added to check the log level of warnings and ignore any messages below WARN level. These messages are cleared and not written to the +server.log+ file. While this measure mitigates much of the performance degradation, the issue may still present to varying degrees, depending on the JDBC implementation being used. To avoid the performance issue completely, users can raise this threshold by setting the `org.hibernate` logging category to ERROR. Care should be taken before making this change, however, as ignoring warnings below the ERROR level can obfuscate possible problems in the database.
Clone Of:
: 1096043 (view as bug list)
Environment:
Last Closed: 2014-05-27 18:10:12 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Pavel Slavicek 2014-05-06 12:22:17 UTC
Description of problem:
We have found a performance regression with EAP 6.2.3 CP build. We see ~20% drop of throughput with complex enterprise application (EJB, JPA, JMS, JSP). 

Version-Release number of selected component (if applicable):
EAP 6.2.3.CP.CR2

How reproducible:
Always, we have stable results

Actual results:
We see a performance regression with Daytrader benchmark. Results show ~20% drop on TPS with complex trader scenario (EE application with JMS).

Expected results:
CP release should not introduce any regressions.

Additional info:
EAP 6.2.3 CP release contains upgrades of many components. We have tried to isolate cause of this regression and it looks like that upgrade of Hibernate in EAP 6.2.3 CP causes this regression. We have re-executed performance test with modified build with downgraded Hibernate and we do not see any performance regressions.

Comment 1 Brett Meyer 2014-05-06 14:17:51 UTC
Discussing with the team -- most likely due to https://hibernate.atlassian.net/browse/HHH-3051

Comment 2 Brett Meyer 2014-05-06 14:46:29 UTC
Pavel, can you confirm that the 20% drop is when compared against 6.2.0 (ORM 4.2.7.SP1)?

Comment 3 Martin Simka 2014-05-06 15:09:43 UTC
yes, it's when compared against 6.2.0. We also tried to execute performance test with EAP 6.2.3 and hibernate jars from 6.2.0 and in that case there was no performance regression.

Comment 5 Brett Meyer 2014-05-09 16:18:07 UTC
Will be in the 1096304 component upgrade

Comment 6 Pavel Slavicek 2014-05-19 09:06:30 UTC
ON_QA failed.

We are reopening this BZ because we see same performance regression with EAP 6.2.3 CP CR3 build. 

Version-Release number of selected component (if applicable):
EAP 6.2.3.CP.CR3

How reproducible:
Always, we have stable results

Actual results:
We see a performance regression with Daytrader benchmark. Results show ~20% drop on TPS with complex trader scenario (EE application with JMS). We see a higher regression when component is under stress.

Expected results:
CP release should not introduce any regressions.

Additional info:
Root cause of the performance regression:
----------------------------------------
This performance regression is caused by commit a0b01c5483d1f7857c640070b0cafd2c436e5fb5 [1] in file /hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcCoordinatorImpl.java

 protected void close(Statement statement) {
  LOG.tracev( "Closing prepared statement [{0}]", statement );
+
+ // Important for Statement caching -- some DBs (especially Sybase) log warnings on every Statement under
+ // certain situations.
+ sqlExceptionHelper().logAndClearWarnings( statement );


[1] http://git.app.eng.bos.redhat.com/git/hibernate/hibernate-core.git/commit/?id=a0b01c5483d1f7857c640070b0cafd2c436e5fb5

Comment 7 Brett Meyer 2014-05-19 14:28:52 UTC
Pavel, confused by this.  That area is what we corrected under https://hibernate.atlassian.net/browse/HHH-9174 and the performance team (Andrig) confirmed that the regression was fixed.  Can you confirm the ORM version?  https://bugzilla.redhat.com/show_bug.cgi?id=1096304 should have upgraded it to 4.2.7.SP4-redhat-1

Comment 8 Brett Meyer 2014-05-19 14:42:34 UTC
Actually, let me correct myself.  The performance issue stems from Statement#getWarnings apparently being a hotspot for certain JDBC providers (not all of them).  ORM logs any warnings that the database attached to an executed Statement (important for most users), as well as clears the warnings (absolutely vital for Statement caching).  Our fix for the perf team was simply to surround the logging with a "if (LOG.isEnabled(Level.WARN))", but that's probably not accomplishing anything for QE.

I'm not sure what else could be done to improve the situation.  This log/clear capability is something we had for a long time, but it was broken back in 4.1.x (which probably "improved" our performance).  We re-introduced it in 4.2.x due to customer complaints -- both logging and clearing the warnings are important for most users.  Skipping the logging entirely through a config prop is doable, but I'd argue that the logging should happen by default since it's important debugging info.

Thoughts?

Comment 9 Brett Meyer 2014-05-19 19:26:15 UTC
Note that this was always the case, up until 4.1.x when we removed the JDBC proxies for performance reasons and the Statement logging was accidentally skipped.  Had we fixed it correctly back in 4.1.x, there wouldn't be a "regression" right now -- performance would have always been the same (albeit slower).  It's a vital issue that has to be corrected.

Yes, for the original issue on Sybase, the warning was due to a bug in the JBDC driver and was completely useless.  But generally, if the database has a warning, it can be a legitimate issue and could definitely be important for debugging, regardless of the Dialect, etc.

Again, there are 2 different things happening here:

1.) If Statement#getWarnings is not empty, log them.
2.) Statement#clearWarnings

#2 is completely independent of #1 (happens without calling #getWarnings).  #1 is the "regression", but imo is really important for debugging (and was the case up until we broke it during the proxy removal in 4.1.x).  

Any new setting we introduce would need to allow the logging to happen by default.  I'm not sure how many users would actively want to disable the Statement warnings from being logged, especially since the same effect can be achieved by bumping up the level to ERROR.

In any case, this should not be a blocker and I'd still recommend calling 1094756 "done" with the fixes we introduced.

Comment 10 Brett Meyer 2014-05-19 19:27:28 UTC
Recommend not considering this urgent, nor a blocker.  But in the end, the fixes are available and "correct" the performance if log levels are increased to ERROR.

Comment 15 Scott Mumford 2014-05-23 03:36:03 UTC
Hi Andy,
I've added a draft release note text and marked this bug for inclusion in the 6.2.3 Release Notes document.

Please review and comment if the draft is inaccurate in any way.

Comment 16 sgilda 2014-05-23 13:06:07 UTC
The release note for this was not generated automatically by BugDash, so I added it manually


Note You need to log in before you can comment on or make changes to this bug.