Announcement

Collapse
No announcement yet.
X
Collapse
  • Page of 1
  • Filter
  • Time
Clear All
new posts
Previous template Next
    #1

    Connection pool management with server-side requests

    Hi,

    We're using SmartGWT 4.1. After several tests and benchmarks of a server side asynchronous process that is critical for our application, we found several problems that raise concern over connection pool configuration and management with SmartGWT.

    c3p0 CP configuration (development):

    Code:
    <New class="com.mchange.v2.c3p0.ComboPooledDataSource">
  <Set name="driverClass">oracle.jdbc.driver.OracleDriver</Set>
  <Set name="jdbcUrl">jdbc:oracle:thin:@X.X.X.X:1521:fircocdb</Set>
  <Set name="user"></Set>
  <Set name="password"></Set>
  <Set name="initialPoolSize">20</Set>
  <Set name="maxPoolSize">50</Set>
  <Set name="testConnectionOnCheckin">true</Set>
  <Set name="preferredTestQuery">SELECT 1 FROM DUAL</Set>
</New>
    server.properties related section:

    Code:
    datasources.pool.enabled: true

sql.defaultDatabase: FIRCO

sql.FIRCO.driver.name: jdbc/fircocdb
sql.FIRCO.database.type: oracle
sql.FIRCO.interface.type: jndi
#Deactivate SmartGWT default pooling through DBCP, as the JNDI resource will handle that
sql.pool.enabled: false
    === 1st issue (high priority) ===

    The critical process uses a thread pool with a capacity of 20 simultaneous threads, that will create DSRequest's and query database (SELECT statements only, not transactional).

    With a max size of 50 connections, connection pool is maxed out during execution: threads are blocking awaiting to acquire a connection:

    Code:
    === 2014-02-11 13:06:32,497 [hz.cdb_cluster.cached.thread-7] DEBUG com.mchange.v2.resourcepool.BasicResourcePool - acquire test -- pool is already maxed out. [managed: 50; max: 50]
=== 2014-02-11 13:06:32,497 [hz.cdb_cluster.cached.thread-7] DEBUG com.mchange.v2.resourcepool.BasicResourcePool - awaitAvailable(): com.mchange.v2.c3p0.impl.NewPooledConnection@4c63e387
=== 2014-02-11 13:06:32,497 [hz.cdb_cluster.cached.thread-7] DEBUG com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@18f2825e [managed: 50, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@4c63e387)
    Connections are not returned to the pool after execution (please confirm). Checking the logs, I detected several traces saying connection releasing occur on object finalization. To validate this, I triggered a garbage collect when process was stuck as above: it released connections and process was able to finish.
    Traces logged on GC:
    Code:
    === 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1784127230
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1784127230"
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 87047544
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "87047544"
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1345818013
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1345818013"
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1170594405
=== 2014-02-11 13:08:31,192 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1170594405"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1460384072
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1460384072"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 754901906
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "754901906"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 682820957
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "682820957"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1261850427
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1261850427"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1748247612
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1748247612"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 292261196
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "292261196"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 54902224
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "54902224"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1765383577
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1765383577"
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1718430819
=== 2014-02-11 13:08:31,193 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1718430819"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1598054270
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1598054270"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1876231801
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1876231801"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1315826676
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1315826676"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1894848993
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1894848993"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1464054596
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1464054596"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 2059252786
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "2059252786"
=== 2014-02-11 13:08:31,194 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1917957294
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1917957294"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1157390594
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1157390594"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1271776167
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1271776167"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1687555278
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1687555278"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 2145566539
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "2145566539"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1541415546
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1541415546"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 654484598
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "654484598"
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1588781809
=== 2014-02-11 13:08:31,195 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1588781809"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 408340331
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "408340331"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1516453476
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1516453476"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1367870063
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1367870063"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1176047503
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1176047503"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 823165864
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "823165864"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 684396120
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "684396120"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1232350613
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "1232350613"
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 703785687
=== 2014-02-11 13:08:31,196 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "703785687"
=== 2014-02-11 13:08:31,197 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 687578799
=== 2014-02-11 13:08:31,197 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "687578799"
=== 2014-02-11 13:08:31,197 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 688614482
=== 2014-02-11 13:08:31,197 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "688614482"
=== 2014-02-11 13:08:31,197 [Finalizer] DEBUG SQLDriver - Freeing SQLDriver dbConnection 229680832
=== 2014-02-11 13:08:31,197 [Finalizer] DEBUG SQLConnectionManager - About to close NewProxyConnection with hashcode "229680832"
    This way of handling connection release is very surprising. How can we count on GC to free connections and make them return to the pool?
    It's also useless to try increasing the size of the pool: everything depends on number of connections acquired between 2 garbage collections.
    Note: this seems to be a different behaviour than with HTTP request-tied DSRequest; in the logs, connections seem released by http listener thread (on request response?).


    === 2nd issue (medium prio - workarounded) ===

    This issue happens when using Apache DBCP 1.4 on Jetty, with Oracle 11gr2. Never reproduced with SQL Server and/or c3p0 and/or Tomcat DBCP.
    However, this still raises concern for other configurations we need to support (websphere, weblogic) and for SmartGWT connection pool management in general.

    When connection pool above is shared between different DB users (SmartGWT, Spring JDBC templates), and we run test described above, we get intermittent I/O or SQL exceptions like 'Socket closed'. Example:
    Code:
    Caused by: java.sql.SQLException: Connexion interrompue
	at oracle.jdbc.driver.PhysicalConnection.getMetaData(PhysicalConnection.java:4265)
	at org.apache.commons.dbcp.DelegatingConnection.getMetaData(DelegatingConnection.java:345)
	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.getMetaData(PoolingDataSource.java:245)
	at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:285)
    To find root cause, I splitted jndi resources into 2, 1 for SmartGWT, 1 for the rest: intermittent exceptions disappeared, but I still get this kind of error in SmartGWT logs:

    Code:
    === 2014-02-11 13:55:44,027 [localTaskExecutor-19] INFO  SQLDriver - [builtinApplication.null] Execute of select: SELECT CIF_DOCUMENT.COUNTRY_ID, CIF_DOCUMENT.CUSTOMER_ID, CIF_DOCUMENT.EXPIRY_DATE, CIF_DOCUMENT.ID, CIF_DOCUMENT.ISSUE_DATE, CIF_DOCUMENT.REFERENCE, CIF_DOCUMENT.TYPE_ID, CIF_DOCUMENT_TYPE.NAME AS TYPE, GEO_COUNTRY.NAME AS COUNTRY FROM CIF_DOCUMENT, GEO_COUNTRY, CIF_DOCUMENT_TYPE WHERE (CIF_DOCUMENT.CUSTOMER_ID=1276) AND CIF_DOCUMENT.TYPE_ID = CIF_DOCUMENT_TYPE.ID AND CIF_DOCUMENT.COUNTRY_ID = GEO_COUNTRY.ID on db: FIRCO threw exception: java.sql.SQLException: Erreur d'E/S: socket closed - assuming stale connection and retrying query.
    So I guess socket closed exceptions are somehow workarounded by a retry.
    What are the possible causes and consequences of such exceptions? My first thought is connection isn't just returned to the pool, underlying connection is closed at some point.


    We are now at a point we need to decide if we can trust DSRequests when they are not tied to a user request and started by an asynchronous process. If we can't get confident on that point we'll have to move to a 100% JDBC-like solution without using SmartGWT server side datasources, although we chose Power edition mainly for that purpose.

    Thanks in advance for your answer
    Antoine
    Tags: None
    #2
    First issue - read docs for server-side API DSRequest.freeAllResources(). It explains situations in which resources are immediately and automatically reclaimed vs situations where you would need to call freeAllResources() to release connections to the pool.

    Second issue: Oracle (and some other DBs) can be configured to close idle connections. Various connection pools have keepAlive or eviction settings that can be used to ensure that dead connections are never returned to application code, but very often, people omit these settings or get them wrong, so SmartGWT has a fallback of retrying with a new connection if we get an obviously closed one from a pool.

    You can avoid this fallback ever happening by making sure your pool's eviction or keepAlive settings match the DB's policy about closing idle connections.

    Comment

      #3
      Thanks for this quick and very valuable answer.

      1st issue: exactly the situation I ran in (clob field). Also good to know that we have a way to force connection release.

      2nd issue: with testOnBorrow activated (and validation query), wouldn't it be sufficient to prevent such closed connection reuse? Anyway, problem never reproduced with other pool implementations, without specifying keep alive settings.

      Comment

        #4
        2nd issue: that just suggests that the other pooling implementations probably default to evictions/keepAlive/testOnBorrow behavior in the environment where you tested, whereas the Apache DBCP pool did not (in the environment where you tested it).

        Comment

        Previous template Next
        Working...
        X