Bug 1094756
Summary: | [QE] (6.2.3) HHH-9170 HHH-9174 ORM Performance regression | |||
---|---|---|---|---|
Product: | [JBoss] JBoss Enterprise Application Platform 6 | Reporter: | Pavel Slavicek <pslavice> | |
Component: | Hibernate | Assignee: | Brett Meyer <brmeyer> | |
Status: | CLOSED NOTABUG | QA Contact: | Martin Simka <msimka> | |
Severity: | urgent | Docs Contact: | Russell Dickenson <rdickens> | |
Priority: | urgent | |||
Version: | 6.2.3 | CC: | anmiller, cdewolf, jkudrnac, jmartisk, lfuka, msimka, myarboro, sgilda, smumford, theute, weli, zroubali | |
Target Milestone: | CR4 | Keywords: | Regression | |
Target Release: | EAP 6.2.3 | |||
Hardware: | Unspecified | |||
OS: | Unspecified | |||
Whiteboard: | ||||
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.
|
Story Points: | --- | |
Clone Of: | ||||
: | 1096043 (view as bug list) | Environment: | ||
Last Closed: | 2014-05-27 18:10:12 UTC | Type: | Bug | |
Regression: | --- | Mount Type: | --- | |
Documentation: | --- | CRM: | ||
Verified Versions: | Category: | --- | ||
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
Cloudforms Team: | --- | Target Upstream Version: | ||
Embargoed: | ||||
Bug Depends On: | 1096043 | |||
Bug Blocks: | 1067532, 1096304 |
Description
Pavel Slavicek
2014-05-06 12:22:17 UTC
Discussing with the team -- most likely due to https://hibernate.atlassian.net/browse/HHH-3051 Pavel, can you confirm that the 20% drop is when compared against 6.2.0 (ORM 4.2.7.SP1)? 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. Will be in the 1096304 component upgrade 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 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 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? 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. 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. 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. The release note for this was not generated automatically by BugDash, so I added it manually |