Anonymous | Login
Project:
RSS
  
News | My View | View Issues | Roadmap | Summary

View Issue DetailsJump to Notes ] Issue History ] Print ]
ID
0034534
TypeCategorySeverityReproducibilityDate SubmittedLast Update
defect[Openbravo ERP] A. Platformmajorhave not tried2016-11-15 15:242016-12-16 18:38
ReporteralostaleView Statuspublic 
Assigned Toalostale 
PrioritynormalResolutionfixedFixed in Version3.0PR17Q1
StatusclosedFix in branchFixed in SCM revisiondac0b38ed41e
ProjectionnoneETAnoneTarget Version
OSAnyDatabaseAnyJava version
OS VersionDatabase versionAnt version
Product VersionSCM revision 
Review Assigned Tocaristu
Web browser
ModulesCore
Regression level
Regression date
Regression introduced in release
Regression introduced by commit
Triggers an Emergency PackNo
Summary

0034534: StatementFinalizer causes some overhead on each statement

DescriptionDefault 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 ReproduceEasier 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 SolutionThe 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.
TagsPerformance
Attached Filespng file icon Selection_125.png [^] (51,050 bytes) 2016-11-15 15:39

- Relationships Relation Graph ] Dependency Graph ]
related to feature request 00295643.0PR15Q4 closedinigosanchez Include Connection Pool module into distribution 

-  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
Powered by Mantis Bugtracker