Openbravo Issue Tracking System - Openbravo ERP
View Issue Details
0034534Openbravo ERPA. Platformpublic2016-11-15 15:242016-12-16 18:38
alostale 
alostale 
normalmajorhave not tried
closedfixed 
5
 
3.0PR17Q1 
caristu
Core
No
0034534: StatementFinalizer causes some overhead on each statement
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 [^]
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).
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.
Performance
related to feature request 00295643.0PR15Q4 closed inigosanchez Include Connection Pool module into distribution 
png Selection_125.png (51,050) 2016-11-15 15:39
https://issues.openbravo.com/file_download.php?file_id=10047&type=bug
png
Issue History
2016-11-15 15:24alostaleNew Issue
2016-11-15 15:24alostaleAssigned To => platform
2016-11-15 15:24alostaleModules => Core
2016-11-15 15:24alostaleTriggers an Emergency Pack => No
2016-11-15 15:24alostaleSteps to Reproduce Updatedbug_revision_view_page.php?rev_id=13750#r13750
2016-11-15 15:31alostaleSteps to Reproduce Updatedbug_revision_view_page.php?rev_id=13751#r13751
2016-11-15 15:39alostaleSteps to Reproduce Updatedbug_revision_view_page.php?rev_id=13752#r13752
2016-11-15 15:39alostaleFile Added: Selection_125.png
2016-11-15 15:40alostaleTag Attached: Performance
2016-11-15 15:40alostaleStatusnew => scheduled
2016-11-15 15:40alostaleAssigned Toplatform => alostale
2016-11-15 15:40alostaleReview Assigned To => caristu
2016-11-15 15:45alostaleSteps to Reproduce Updatedbug_revision_view_page.php?rev_id=13753#r13753
2016-11-15 15:47alostaleRelationship addedrelated to 0029564
2016-11-15 15:48hgbotCheckin
2016-11-15 15:48hgbotNote Added: 0091574
2016-11-15 15:49hgbotStatusscheduled => resolved
2016-11-15 15:49hgbotResolutionopen => fixed
2016-11-15 15:49hgbotFixed in SCM revision => http://code.openbravo.com/erp/devel/pi/rev/dac0b38ed41ef6e2ae7c17f2e7824718c2a95504 [^]
2016-11-18 10:59caristuNote Added: 0091652
2016-11-18 10:59caristuStatusresolved => closed
2016-11-18 10:59caristuFixed in Version => 3.0PR17Q1
2016-12-16 18:38hudsonbotCheckin
2016-12-16 18:38hudsonbotNote Added: 0092630

Notes
(0091574)
hgbot   
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   
2016-11-18 10:59   
Verified
(0092630)
hudsonbot   
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