Announcement

Collapse
No announcement yet.
X
  • Filter
  • Time
Clear All
new posts

    Connections leak in SQL Datasource

    Smartgwt EE eval 20120523 (and older: 20120423)

    I have problems with leaking of not closed connections from Smartgwt SQL Datasource.
    After ecach fetch (or other operation such as load metadata from table) count of open sql connections rise (4 for loading new datasource data and fetch and 1 for paged fetch).


    My server.properties:
    Code:
    webRoot: __USE_CONTAINER__
    
    gwtModuleName: app
    
    isomorphicPathRootRelative: $gwtModuleName/sc
    
    
    hibernate.config.lookupStyle: spring
    hibernate.config.bean: sessionFactory
    
    project.datasources: $webRoot/ds, $webRoot/shared/ds
    project.ui: $webRoot/shared/ui
    project.apps: $webRoot/shared/app
    
    sql.JNDI.driver.name= java:comp/env/jdbc/sql_db
    sql.JNDI.database.type= sqlserver
    sql.JNDI.interface.type= jndi
    sql.JNDI.autoJoinTransactions: true
    Jndi (definied in Tomcat):
    Code:
      <Resource name="jdbc/sql_db" auth="Container" type="javax.sql.DataSource"
                   maxActive="5" maxIdle="2" maxWait="5000"
                   timeBetweenEvictionRunsMillis="5000"
                   defaultTransactionIsolation="4"
            	factory="org.apache.commons.dbcp.BasicDataSourceFactory"
            	logAbandoned="true"
            	validationQuery="SELECT 1"
                   username="UUUUU" password="PPPPPPPPPPPP" driverClassName="net.sourceforge.jtds.jdbc.Driver"
                   url="jdbc:jtds:sqlserver://HOST:1433;DatabaseName=DBDBDBD;SelectMethod=Cursor;"/>
    As you can see: I use hibernate datasources (connected to other JNDI ds) and SQL datasources in the same appliaction. Physically two JNDI (definied in Tomcat) are connected to the same database.
    I am using jTDS driver with SQL SERVER 2008 database.

    Smartgwt Sql datasource example:
    Code:
    <DataSource
        ID="dsdb_sqlKlienci"
        serverType="sql"
        tableName="Klient"
        autoDeriveSchema="true"
        dbName="JNDI"
    >
    
    <fields>
      <field name="KlientID" primaryKey="true" type="int"/>
    </fields>
    
    </DataSource>

    Hibernate smartwt datasources work pefrectly well: there are no connections leakage.
    But after a few refreshes (usages) of sql smartgwt datasources limit of available conenctions is exceeded. It is stranbe beacause it is exceeded for Hibernate datasources!

    In log I vave lots of exceptions such as:
    Code:
    === 2012-05-23 15:45:08,410 [80-1] INFO  IDACall - Performing 1 operation(s)
    === 2012-05-23 15:45:08,410 [80-1] DEBUG AppBase - [builtinApplication.dsdb_sqlKlienci_fetch] No userTypes defined, allowing anyone access to all operations for this application
    === 2012-05-23 15:45:08,411 [80-1] DEBUG AppBase - [builtinApplication.dsdb_sqlKlienci_fetch] No public zero-argument method named '_dsdb_sqlKlienci_fetch' found, performing generic datasource operation
    === 2012-05-23 15:45:08,411 [80-1] INFO  SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Performing fetch operation with
    	criteria: {}	values: {}
    === 2012-05-23 15:45:08,411 [80-1] INFO  SQLWhereClause - [builtinApplication.dsdb_sqlKlienci_fetch] empty condition
    === 2012-05-23 15:45:08,411 [80-1] INFO  SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
    === 2012-05-23 15:45:08,412 [80-1] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
    === 2012-05-23 15:45:08,412 [80-1] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Eval'd row count query: SELECT COUNT(*) FROM Klient WHERE ('1'='1')
    === 2012-05-23 15:45:08,419 [80-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.dsdb_sqlKlienci_fetch] Returning pooled Connection
    === 2012-05-23 15:45:08,420 [80-1] DEBUG SQLTransaction - [builtinApplication.dsdb_sqlKlienci_fetch] Started new JNDI transaction "0"
    === 2012-05-23 15:45:08,420 [80-1] INFO  SQLDriver - [builtinApplication.dsdb_sqlKlienci_fetch] Executing SQL query on 'JNDI': SELECT COUNT(*) FROM Klient WHERE ('1'='1')
    === 2012-05-23 15:45:08,422 [80-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.dsdb_sqlKlienci_fetch] Initializing SQL config for 'HSQLDB' from system config - using DriverManager:  org.hsqldb.jdbcDriver
    === 2012-05-23 15:45:08,423 [80-1] ERROR SQLConnectionManager - [builtinApplication.dsdb_sqlKlienci_fetch] Caught exception
    java.lang.ClassNotFoundException: org.hsqldb.jdbcDriver
    	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1387)
    	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1233)
    	at java.lang.Class.forName0(Native Method)
    	at java.lang.Class.forName(Class.java:169)
    	at com.isomorphic.base.Reflection.classForName(Reflection.java:139)
    	at com.isomorphic.sql.PoolableSQLConnectionFactory.makeUnpooledObject(PoolableSQLConnectionFactory.java:222)
    	at com.isomorphic.sql.PoolableSQLConnectionFactory.makeObject(PoolableSQLConnectionFactory.java:340)
    	at com.isomorphic.pool.PoolManager.borrowObject(PoolManager.java:76)
    	at com.isomorphic.sql.SQLConnectionManager.getConnection(SQLConnectionManager.java:156)
    	at com.isomorphic.sql.SQLMetaData.conn(SQLMetaData.java:85)
    	at com.isomorphic.sql.SQLMetaData.getMetaData(SQLMetaData.java:102)
    	at com.isomorphic.sql.SQLServerDriver.supportsSQLLimit(SQLServerDriver.java:120)
    	at com.isomorphic.sql.SQLDataSource.executeWindowedSelect(SQLDataSource.java:1702)
    	at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1317)
    	at com.isomorphic.sql.SQLDataSource.processRequest(SQLDataSource.java:293)
    	at com.isomorphic.sql.SQLDataSource.executeFetch(SQLDataSource.java:237)
    	at com.isomorphic.datasource.DataSource.execute(DataSource.java:1289)
    	at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:725)
    	at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:658)
    	at com.isomorphic.application.AppBase.execute(AppBase.java:491)
    	at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:1954)
    	at com.isomorphic.servlet.IDACall.handleDSRequest(IDACall.java:199)
    	at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:156)
    	at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:121)
    	at com.isomorphic.servlet.IDACall.doPost(IDACall.java:73)
    	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    	at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:152)
    	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    	at my.web.ResponseHaeaderFilter.doFilter(ResponseHaeaderFilter.java:59)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:344)
    	at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:79)
    	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:356)
    	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:150)
    	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
    	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
    	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
    	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
    	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
    	at java.lang.Thread.run(Thread.java:662)
    === 2012-05-23 15:45:08,423 [80-1] INFO  SQLServerDriver - [builtinApplication.dsdb_sqlKlienci_fetch] supportsSQLLimit on db: JNDI threw exception: java.sql.SQLException: java.sql.SQLException: java.lang.ClassNotFoundException: org.hsqldb.jdbcDriver
    === 2012-05-23 15:45:08,423 [80-1] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] JDBC driver windowed select rows 0->75, result size 75. Query: SELECT Klient.AdresIKorespondencjiID, Klient.AdresSiedzibyID, Klient.AktualneZatrudnienie, Klient.BranzaID, Klient.DataRozpoczeciaDzial, Klient.EDGNr, Klient.EDGUrzad, Klient.FormaPrawnaID, Klient.FormaRozliczeniaPodID, Klient.FunduszID, Klient.KRS, Klient.KlasyfikacjaMSPID, Klient.KlientID, Klient.NIP, Klient.Nazwa, Klient.NazwaS, Klient.PKDID, Klient.PlanowaneZatrudnienie, Klient.REGON, Klient.SadRejestrowy, Klient.TypSprawozdawczosciID, Klient.Usuniety FROM Klient WHERE ('1'='1')
    === 2012-05-23 15:45:08,440 [80-1] INFO  DSResponse - [builtinApplication.dsdb_sqlKlienci_fetch] DSResponse: List with 61 items
    === 2012-05-23 15:45:08,441 [80-1] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
    === 2012-05-23 15:45:08,441 [80-1] DEBUG SQLTransaction - Committing JNDI transaction "0"
    === 2012-05-23 15:45:08,454 [80-1] DEBUG XML - Parsed XML from (in memory stream): 1ms
    === 2012-05-23 15:45:08,457 [80-1] DEBUG RPCManager - non-DMI response, dropExtraFields: false
    === 2012-05-23 15:45:08,468 [80-1] DEBUG SQLTransaction - Ending JNDI transaction "0"
    === 2012-05-23 15:45:08,469 [80-1] ERROR SQLConnectionManager - Error attempting to commit and close a connection
    java.sql.SQLException: Already closed.
    	at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:84)
    	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:181)
    	at org.apache.commons.dbcp.DelegatingConnection.close(DelegatingConnection.java:214)
    	at org.apache.commons.dbcp.PoolableConnection.reallyClose(PoolableConnection.java:102)
    	at com.isomorphic.sql.SQLConnectionManager.free(SQLConnectionManager.java:282)
    	at com.isomorphic.sql.SQLTransaction.endTransaction(SQLTransaction.java:221)
    	at com.isomorphic.sql.SQLTransaction.endTransaction(SQLTransaction.java:212)
    	at com.isomorphic.sql.SQLDataSource.freeResources(SQLDataSource.java:2503)
    	at com.isomorphic.datasource.DSRequest.freeResources(DSRequest.java:3449)
    	at com.isomorphic.rpc.RPCManager.completeResponse(RPCManager.java:1325)
    	at com.isomorphic.rpc.RPCManager.send(RPCManager.java:592)
    	at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:156)
    	at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:121)
    	at com.isomorphic.servlet.IDACall.doPost(IDACall.java:73)
    	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    	at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:152)
    	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    	at my.web.ResponseHaeaderFilter.doFilter(ResponseHaeaderFilter.java:59)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:344)
    	at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:79)
    	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:356)
    	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:150)
    	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
    	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
    	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
    	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
    	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
    	at java.lang.Thread.run(Thread.java:662)
    How to solve this problem? How to properly configure JNDI datasource (unfortunately my admin console is not working at all - I created another post about that problem)?

    #2
    I did not surrender.

    Now: I don't use configuration in server.properties.
    Admin Console showed me that I can use explicit JNDI connection name in "dbName" datasource parameter.

    So now I have:
    Code:
    <DataSource
        ID="dsdb_sqlKlienci"
        serverType="sql"
        tableName="Klient"
        autoDeriveSchema="true"
    dbName="java:comp/env/jdbc/sql_db"
    >
    
    <fields>
      <field name="KlientID" primaryKey="true" type="int"/>
    </fields>
    
    </DataSource>
    And it works. Connections are allocated but slq datasource seems to not return connections to jndi pool. It takes a few (6-7 ?) conenctions and uses them in its own pool fo a few minutes. Then it releases it to the jndi pool.

    * So now question: how to turn this off? *
    It is rather inefficient: suppose if you have 50 datasources. Application will use be 300 connections to db.

    Server log:
    Code:
        criteria:{
        },
        operationConfig:{
            dataSource:"dsdb_sqlKlienci",
            operationType:"fetch",
            textMatchStyle:"substring"
        },
        startRow:0,
        endRow:75,
        componentId:"isc_ListGrid_6",
        appID:"builtinApplication",
        operation:"dsdb_sqlKlienci_fetch",
        oldValues:{
        }
    }
    === 2012-05-24 13:29:08,918 [80-4] INFO  IDACall - Performing 1 operation(s)
    === 2012-05-24 13:29:08,919 [80-4] DEBUG AppBase - [builtinApplication.dsdb_sqlKlienci_fetch] No userTypes defined, allowing anyone access to all operations for this application
    === 2012-05-24 13:29:08,919 [80-4] DEBUG AppBase - [builtinApplication.dsdb_sqlKlienci_fetch] No public zero-argument method named '_dsdb_sqlKlienci_fetch' found, performing generic datasource operation
    === 2012-05-24 13:29:08,919 [80-4] INFO  SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Performing fetch operation with
    	criteria: {}	values: {}
    === 2012-05-24 13:29:08,919 [80-4] INFO  SQLWhereClause - [builtinApplication.dsdb_sqlKlienci_fetch] empty condition
    === 2012-05-24 13:29:08,919 [80-4] INFO  SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
    === 2012-05-24 13:29:08,920 [80-4] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
    === 2012-05-24 13:29:08,920 [80-4] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Eval'd row count query: SELECT COUNT(*) FROM Klient WHERE ('1'='1')
    === 2012-05-24 13:29:08,921 [80-4] DEBUG PoolableSQLConnectionFactory - [builtinApplication.dsdb_sqlKlienci_fetch] Returning unpooled Connection
    === 2012-05-24 13:29:08,921 [80-4] INFO  SQLDriver - [builtinApplication.dsdb_sqlKlienci_fetch] Executing SQL query on 'java:comp/env/jdbc/sql_db': SELECT COUNT(*) FROM Klient WHERE ('1'='1')
    === 2012-05-24 13:29:08,922 [80-4] DEBUG SQLServerDriver - [builtinApplication.dsdb_sqlKlienci_fetch] SQL Server version is '10.00.5500'
    === 2012-05-24 13:29:08,922 [80-4] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Using SQL Limit query
    === 2012-05-24 13:29:08,922 [80-4] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] Using PK as default sorter: KlientID
    === 2012-05-24 13:29:08,922 [80-4] DEBUG SQLDataSource - [builtinApplication.dsdb_sqlKlienci_fetch] SQL windowed select rows 0->75, result size 75. Query: SELECT * FROM (SELECT *, ROW_NUMBER() OVER (ORDER BY x.KlientID) AS rowID FROM (SELECT TOP 100 PERCENT  Klient.AdresIKorespondencjiID, Klient.AdresSiedzibyID, Klient.AktualneZatrudnienie, Klient.BranzaID, Klient.DataRozpoczeciaDzial, Klient.EDGNr, Klient.EDGUrzad, Klient.FormaPrawnaID, Klient.FormaRozliczeniaPodID, Klient.FunduszID, Klient.KRS, Klient.KlasyfikacjaMSPID, Klient.KlientID, Klient.NIP, Klient.Nazwa, Klient.NazwaS, Klient.PKDID, Klient.PlanowaneZatrudnienie, Klient.REGON, Klient.SadRejestrowy, Klient.TypSprawozdawczosciID, Klient.Usuniety FROM Klient WHERE ('1'='1')) x) y WHERE y.rowID BETWEEN 1 AND 75
    === 2012-05-24 13:29:08,923 [80-4] DEBUG PoolableSQLConnectionFactory - [builtinApplication.dsdb_sqlKlienci_fetch] Returning unpooled Connection
    === 2012-05-24 13:29:08,928 [80-4] INFO  DSResponse - [builtinApplication.dsdb_sqlKlienci_fetch] DSResponse: List with 61 items
    === 2012-05-24 13:29:08,928 [80-4] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
    === 2012-05-24 13:29:08,939 [80-4] DEBUG XML - Parsed XML from (in memory stream): 1ms
    === 2012-05-24 13:29:08,940 [80-4] DEBUG RPCManager - non-DMI response, dropExtraFields: false
    === 2012-05-24 13:29:08,950 [80-4] DEBUG XML - Parsed XML from (in memory stream): 1ms

    Comment


      #3
      You should see that pooling is automatically disabled when JNDI is used, but regardless, you can set sql.pool.enabled:false to turn off.

      Comment


        #4
        I finally found cause of this problem: hibernate was saturating its connection pool.
        This bug (?) appeared _only when_ I was making a call to other database (smartgwt sql datasource) and call to hibernate in very close time dostance.

        The solution was to add
        Code:
        <prop key="hibernate.connection.release_mode">after_statement</prop>
        in hibernate configuration.

        This works for Hibernate 3.3.

        Comment

        Working...
        X