Project:
View Issue Details[ Jump to Notes ] | [ Issue History ] [ Print ] | |||||||
ID | ||||||||
0034534 | ||||||||
Type | Category | Severity | Reproducibility | Date Submitted | Last Update | |||
defect | [Openbravo ERP] A. Platform | major | have not tried | 2016-11-15 15:24 | 2016-12-16 18:38 | |||
Reporter | alostale | View Status | public | |||||
Assigned To | alostale | |||||||
Priority | normal | Resolution | fixed | Fixed in Version | 3.0PR17Q1 | |||
Status | closed | Fix in branch | Fixed in SCM revision | dac0b38ed41e | ||||
Projection | none | ETA | none | Target Version | ||||
OS | Any | Database | Any | Java version | ||||
OS Version | Database version | Ant version | ||||||
Product Version | SCM revision | |||||||
Review Assigned To | caristu | |||||||
Web browser | ||||||||
Modules | Core | |||||||
Regression level | ||||||||
Regression date | ||||||||
Regression introduced in release | ||||||||
Regression introduced by commit | ||||||||
Triggers an Emergency Pack | No | |||||||
Summary | 0034534: StatementFinalizer causes some overhead on each statement | |||||||
Description | Default Openbravo pool is adding StatementFinalizer interceptor [1]. From its documentation: "Keeps track of statements associated with a connection and invokes close upon Connection.close() Useful for applications that dont close the associated statements after being done with a connection." So it can be useful for those statements that are not closed when their connection is returned to the pool. But causes some performance degradation: 1. All statements in a connection are kept in a list till the connection is closed, in practice all statements in a transaction are kept in that list. For long lived transactions (ie. long background processes), the number of statements can be significant causing a big heap usage. 2. For each statement in the transaction it adds some overhead in time: 2.1. When it is created it is added to a list to keep track of it 2.3. When connection is returned to the pool, this list is iterated to close the statements again (even if they were already closed). --- [1] https://tomcat.apache.org/tomcat-7.0-doc/api/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.html [^] | |||||||
Steps To Reproduce | Easier to benchmark preaparing some testing code in an Openbravo running with xmx limited to 600MB. 1. Memory overhead Execute this code: Connection con = OBDal.getInstance().getConnection(); try { long i = 0L; while (true) { if (++i % 10000 == 0) { System.out.println(i); } PreparedStatement st = con.prepareStatement("select count(*) from ad_system"); st.close(); } } catch (SQLException e) { e.printStackTrace(); } ... 2720000 2730000 1f923ef8 77346 [http-8080-3] ERROR org.openbravo.base.exception.OBException - Exception thrown Java heap space java.lang.OutOfMemoryError: Java heap space at java.util.Arrays.copyOf(Arrays.java:3181) at java.util.ArrayList.grow(ArrayList.java:261) at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:235) at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:227) at java.util.ArrayList.add(ArrayList.java:458) at org.apache.tomcat.jdbc.pool.interceptor.StatementFinalizer.createStatement(StatementFinalizer.java:43) at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:69) After creating ~2.7M statements OOM occurs while trying to grow the size of the ArrayList that tracks the statement in the transaction. 2. Time overhead Profile Openbravo and execute this code: Connection con = OBDal.getInstance().getConnection(); try { long i = 0L; while (i < 20000000) { if (++i % 10000 == 0) { System.out.println(i); // connection is returned to the pool, in this moment statements are tried // to be closed again and the list is cleaned up OBDal.getInstance().commitAndClose(); con = OBDal.getInstance().getConnection(); } PreparedStatement st = con.prepareStatement("select count(*) from ad_system"); st.close(); } } catch (SQLException e) { e.printStackTrace(); } OBDal.getInstance().getConnection() consumes 26s (22% of the total time). From those 26s, 24s (90%) is spent in StatementFinalizer closing again the already closed statement. == Removing this finalizer == If finalizer is removed we get: 1. The first code snippet can be run indefinitely, as the used heap remains stable. 2. Time for the second one is reduced from 121s to 89s. Mainly in the overhead for the OBDal.commitAndClose, reduced from 26.9s to 2.6s; and in the prepareStatemt (overhead to maintain the list), reduced from 80s to 70s. (see attached graph). | |||||||
Proposed Solution | The vast majority of statements in Openbravo are managed by the Platform (either DAL or sqlc) so they are properly closed. For those rare cases where they are manually handled, it should be developer's responsibility to properly close them. Therefore, the overhead to include this feature does not pay off the potential benefit it brings, so the proposal is to remove this interceptor. | |||||||
Tags | Performance | |||||||
Attached Files | Selection_125.png [^] (51,050 bytes) 2016-11-15 15:39
| |||||||
Relationships [ Relation Graph ] [ Dependency Graph ] | ||||||||
|
Notes | |
(0091574) hgbot (developer) 2016-11-15 15:48 |
Repository: erp/devel/pi Changeset: dac0b38ed41ef6e2ae7c17f2e7824718c2a95504 Author: Asier Lostalé <asier.lostale <at> openbravo.com> Date: Tue Nov 15 15:47:02 2016 +0100 URL: http://code.openbravo.com/erp/devel/pi/rev/dac0b38ed41ef6e2ae7c17f2e7824718c2a95504 [^] fixed issue 34534: StatementFinalizer causes some overhead on each statement StatementFinalizer caused overhead both in terms of memory (by keeping a list of statements in the current transaction) and time (by trying to close again those statements). This finalizer is no longer used, as the potential benefit is small compared with its price. --- M modules/org.openbravo.apachejdbcconnectionpool/src/org/openbravo/apachejdbcconnectionpool/JdbcExternalConnectionPool.java --- |
(0091652) caristu (developer) 2016-11-18 10:59 |
Verified |
(0092630) hudsonbot (developer) 2016-12-16 18:38 |
A changeset related to this issue has been promoted main and to the Central Repository, after passing a series of tests. Promotion changeset: https://code.openbravo.com/erp/devel/main/rev/dc8bf00badd0 [^] Maturity status: Test |
Issue History | |||
Date Modified | Username | Field | Change |
2016-11-15 15:24 | alostale | New Issue | |
2016-11-15 15:24 | alostale | Assigned To | => platform |
2016-11-15 15:24 | alostale | Modules | => Core |
2016-11-15 15:24 | alostale | Triggers an Emergency Pack | => No |
2016-11-15 15:24 | alostale | Steps to Reproduce Updated | View Revisions |
2016-11-15 15:31 | alostale | Steps to Reproduce Updated | View Revisions |
2016-11-15 15:39 | alostale | Steps to Reproduce Updated | View Revisions |
2016-11-15 15:39 | alostale | File Added: Selection_125.png | |
2016-11-15 15:40 | alostale | Tag Attached: Performance | |
2016-11-15 15:40 | alostale | Status | new => scheduled |
2016-11-15 15:40 | alostale | Assigned To | platform => alostale |
2016-11-15 15:40 | alostale | Review Assigned To | => caristu |
2016-11-15 15:45 | alostale | Steps to Reproduce Updated | View Revisions |
2016-11-15 15:47 | alostale | Relationship added | related to 0029564 |
2016-11-15 15:48 | hgbot | Checkin | |
2016-11-15 15:48 | hgbot | Note Added: 0091574 | |
2016-11-15 15:49 | hgbot | Status | scheduled => resolved |
2016-11-15 15:49 | hgbot | Resolution | open => fixed |
2016-11-15 15:49 | hgbot | Fixed in SCM revision | => http://code.openbravo.com/erp/devel/pi/rev/dac0b38ed41ef6e2ae7c17f2e7824718c2a95504 [^] |
2016-11-18 10:59 | caristu | Note Added: 0091652 | |
2016-11-18 10:59 | caristu | Status | resolved => closed |
2016-11-18 10:59 | caristu | Fixed in Version | => 3.0PR17Q1 |
2016-12-16 18:38 | hudsonbot | Checkin | |
2016-12-16 18:38 | hudsonbot | Note Added: 0092630 |
Copyright © 2000 - 2009 MantisBT Group |