JBoss Database connection reset
Hi Team,
We are using JBoss 5.1 as our server and our application is a simple Spring-MVC based web app. Although we use Spring for our application, we still use JBoss managed DB connection, meaning our DB connection pool is defined in JBoss. In our test environment, we have been noticing very weird log messages. Some of our transactions are taking more than an hour to complete or even mark as failed. Most time for such transactions are spent to get hold of a DB connection from the pool. I am providing the log traces and DB connection config. below. Please suggest if this is a desired behavior or we are missing something in the configuration, or this is a bug in JBoss.
<?xml version="1.0" encoding="UTF-8"?> <datasources> <local-tx-datasource> <jndi-name>XyzDS</jndi-name> <use-java-context>false</use-java-context> <driver-class>oracle.jdbc.driver.OracleDriver</driver-class> <connection-url>jdbc:oracle:thin:@abc.mycompany.com:1222:itdb</connection-url> <user-name>user_name</user-name> <password>password</password> <!-- The minimum connections in a pool/sub-pool --> <min-pool-size>10</min-pool-size> <!-- The maximum connections in a pool/sub-pool --> <max-pool-size>20</max-pool-size> <!-- The time before an unused connection is destroyed --> <!-- NOTE: This is the check period. It will be destroyed somewhere between 1x and 2x this timeout after last use --> <idle-timeout-minutes>10</idle-timeout-minutes> <exception-sorter-class-name>org.jboss.resource.adapter.jdbc.vendor.OracleExceptionSorter</exception-sorter-class-name> <valid-connection-checker-class-name>org.jboss.resource.adapter.jdbc.vendor.OracleValidConnectionChecker</valid-connection-checker-class-name> <!-- ORACLE benefits from prepared statement caching --> <!--<prepared-statement-cache-size>10</prepared-statement-cache-size>--> <!-- Connection Properties --> <!--<connection-property name="autoCommit">false</connection-property>--> <!-- Transaction Properties --> <!--<transaction-isolation>TRANSACTION_READ_COMMITTED</transaction-isolation>--> </local-tx-datasource>
We are using ojdbc6-11.2.0.2.0.jar as our JDBC driver. This is the latest JDBC driver provided by Oracle for Java 6 (we use Java 1.6.0_26).
The log that we are getting are shown below:
Sample 1
2011-08-02 10:36:09,853 DEBUG [com.mycompany.security.dao.impl.SomeDAOImpl][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) someMethod : START
2011-08-02 10:36:09,853 DEBUG [com.mycompany.security.dao.stored_procedure.SomeSpringStoredProcedure][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) executeProc : START
2011-08-02 10:36:09,853 DEBUG [com.mycompany.security.dao.stored_procedure.SomeSpringStoredProcedure][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) InputParams : {input for stored proc invocation}
2011-08-02 10:36:09,853 DEBUG [org.springframework.jdbc.core.JdbcTemplate][execute] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) Calling stored procedure [{call MY_PKG.MY_PROC(?, ?, ?, ?, ?, ?, ?)}]
2011-08-02 10:36:09,854 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils][doGetConnection] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) Fetching JDBC Connection from DataSource
2011-08-02 11:02:47,776 DEBUG [com.mycompany.security.dao.stored_procedure.row_mapper.ASpringRowMapper][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) mapStatusRow :START
2011-08-02 11:02:47,777 DEBUG [com.mycompany.security.dao.stored_procedure.row_mapper.ASpringRowMapper][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) mapStatusRow :END
2011-08-02 11:02:47,781 DEBUG [com.mycompany.security.dao.stored_procedure.SomeSpringStoredProcedure][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) ResultMap : {prints the result of stored proc}
2011-08-02 11:02:47,782 DEBUG [com.mycompany.security.dao.impl.SomeDAOImpl][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) someMethod : END
2011-08-02 11:02:47,782 DEBUG [com.mycompany.security.dao.impl.SomeDAOImpl][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-25) Time spent in DAO --> 1597929ms.
Sample 2
2011-08-02 08:47:17,938 DEBUG [com.mycompany.util.WebAppUtils][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) getUserSessionDetail : START
2011-08-02 08:47:17,939 DEBUG [com.mycompany.authentication.business.dao.util.stored_procedure.GetUserSessionSP][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) executeProc : START2011-08-02 08:47:17,939 DEBUG [com.mycompany.common.dao.impl.UtilityDAOImpl][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) populateDetailsWithSession : START2011-08-02 08:47:17,939 DEBUG [com.mycompany.util.UserSessionCache][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) sessionToken received for validation f8c8f1312273376653
2011-08-02 08:47:17,940 DEBUG [com.mycompany.authentication.business.dao.util.stored_procedure.GetUserSessionSP][debug] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) InputParams:{in_session_id=f8c8f1312273376653}
2011-08-02 08:47:17,940 DEBUG [org.springframework.jdbc.core.JdbcTemplate][execute] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) Calling stored procedure [{call My_PKG.p_get_session_detail(?, ?, ?, ?)}]2011-08-02 08:47:17,940 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils][doGetConnection] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) Fetching JDBC Connection from DataSource
2011-08-02 09:48:23,436 WARN [org.jboss.resource.connectionmanager.TxConnectionManager][warn] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@13493d2
0[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@174ed99a handles=1 lastUse=1312274802338 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@514a02f2 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@5207878f xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@39b0196a txSync=null]
2011-08-02 09:48:23,438 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils][doReleaseConnection] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) Returning JDBC Connection to DataSource
2011-08-02 09:48:23,438 DEBUG [org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator][logTranslation] (http-xyz-ap1.mycompany.com%2F17.108.28.163-6880-19) Translating SQLException with SQL state '08006', error code '17002', message [IO Error: Connection reset]; SQL was [{call MY_PKG.p_get_session_detail(?, ?, ?, ?)}] for task [CallableStatementCallback]
In the second sample, after almost 1 hour, we get a Connection Reset error.
Kindly help us to understand such a behavior.
Thanks,
Niranjan
