首先介紹一個JDBC參數InactiveConnectionTImeout,該參數用于強制回收那些被泄露的連接(長時間不使用的連接、未被程序正確釋放的連接),避免連接池因為泄露導致無連接可用。當然該參數只是起輔助作用,解決問題知道還是在于完善應用程序。
本文和該參數有關,早期的8.1\9.2中,設定該參數時,定時器(內部的連接池維護Task)只會清理那些長期未被使用的空閑連接(從名字上可以看出來),即對于運行一個長時間執行SQL的連接而言,它是不受影響的。但不知道從10.3哪個版本開始(我測試的是10.3.5),該參數對于長時間執行SQL的連接也進行強制回收了(這個比較不合理,雖然對于正在執行的Tx影響不大)。Debug了一下,發現SQL執行時間大于4*InactiveConnectionTimeout時,這個SQL執行完成時,會出現 <BEA-001153> <Forcibly releasing inactive connection "
weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_T4CConnection@1" back into the connection pool "TestDS", currently reserved by: java.lang.Exception這樣的錯誤。
//該線程為內部Task執行線程,該線程目前處于被阻塞狀態,等待SQL執行結束后回收連接
"[STUCK] ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=2 tid=0x2c4d3400 nid=0x1a14 waiting for monitor entry [0x
319bf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jdbc.driver.PhysicalConnection.rollback(PhysicalConnection.java:3896)
- waiting to lock <0x0e6191d8> (a oracle.jdbc.driver.T4CConnection)
at weblogic.jdbc.wrapper.Connection.forcedCleanup(Connection.java:156)
at weblogic.common.resourcepool.ResourcePoolImpl.timeoutInactiveResources(ResourcePoolImpl.java:1955)
at weblogic.common.resourcepool.ResourcePoolImpl.access$8(ResourcePoolImpl.java:1916)
at weblogic.common.resourcepool.ResourcePoolImpl$ResourcePoolMaintanenceTask.timerExpired(ResourcePoolImpl.java:2680)
at weblogic.timers.internal.TimerImpl.run(TimerImpl.java:273)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:178)
//該線程為應用執行線程,目前該線程SQL正在運行,他阻塞(阻塞對象為T4CConnection)了內部Task執行線程
"[STUCK] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=2 tid=0x2c7b4c00 nid=0x1100 runnable [0x2cf7e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
......
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1315)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3576)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3677)
- locked <0x0e6191d8> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1374)
at weblogic.jdbc.wrapper.PreparedStatement.execute(PreparedStatement.java:102)
at com.bea.cs.test.jdbc.DriverTest.inactiveTimeoutTest(DriverTest.java:537)
at jsp_servlet.__ds._jspService(__ds.java:86)
從上面的線程堆棧可以看到,內部Task線程正在調用connection的rollback,即回滾連接上的本地事務。如果應用線程上使用的連接設為auto commit的話,該SQL執行不會被rollback,否則該SQL雖然執行完成也會被rollback調(全局事務中,某個事務分支使用的連接一定是非auto commit的),所以該問題對涉及全局事務的應用影響比較大。
下面我們在看看連接被回收的時間點為什么會出現在3-4個InactiveConnectionTimeout之間。當內部Task執行,發現到了InactiveConnectionTimeout時間點后,它會調用timeoutInactiveResources()方法開始進行連接清理。那么為什么正在執行SQL的連接會被標志為非活動連接呢?這里涉及連接狀態的三個標志位,分別為:conn_in_use,connUsed,hang_state,這三個標志位是其中的關鍵(getUsed()和setUsed()方法中會進行標志位操作及讀取,如果對于某個連接getUsed()返回false的話,該連接會被清理)。下面我們看看其中標志位的變化過程: SQL開始執行時,preInvokeHandler會被這三個標志位進行設定。
初始值如下:
conn_in_use-->true
hang_state-->conn_state_in_use
connUsed-->true
第一次InactiveConnectionTimeout檢查,getUsed返回true,同時調用setUsed(false),標志位變化如下:
conn_in_use-->true
hang_state-->conn_state_idle_suspect
connUsed-->true
第二次InactiveConnectionTimeout檢查,getUsed返回true,同時調用setUsed(false),標志位變化如下:
conn_in_use-->false
hang_state-->conn_state_hang_suspect
connUsed-->false
第三次InactiveConnectionTimeout檢查,getUsed返回true,
hang_state-->conn_state_in_use(從conn_state_hang_suspect變成conn_state_in_use)
同時調用setUsed(false),標志位變化如下:
conn_in_use-->false
connUsed-->false
hang_state-->conn_state_idle_suspect(從conn_state_in_use變成conn_state_idle_suspect)
第四次InactiveConnectionTimeout檢查,getUsed返回false,開始回收該連接。
從上面的變化時間點可以看到從第一次到第四次檢查經歷了完整的3個InactiveConnectionTimout周期,而從SQL執行到第一次檢查點,這個時間小于一個InactiveConnectionTimeout,所以連接開始被回收的時間點介于3-4個InactiveConnectionTimeout之間。