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):
server.properties related section:
=== 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:
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:
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:
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:
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
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>
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
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)
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"
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)
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.
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
Comment