目錄

1. 概述 3

1. 概述

1.1 概述：

應客戶的要求，某局BATCH系統存在的問題進行診斷。經過日誌分析及故障現象定位造成問題的原因，形成此份報告。

為了提供系統的穩定和效能，建議針對性的修改一些引數(會在報告中詳述)，在下次重啟Server時付諸實施。如果需要疑惑的問題，

1.2 系統資訊：

1) 版本資訊

WebLogic Version：WebLogic Server Temporary Patch for CR370091 Tue Jul 08 17:31:21 EDT 2008 WebLogic Server Temporary Patch for CR370915 Tue Jul 15 14:36:25 IST 2008 WebLogic Server 10.0 MP1

 Thu Oct 18 20:17:44 EDT 2007 1005184

Java Version：IBM J9 VM (build 2.3, J2RE 1.5.0 IBM J9 2.3 AIX ppc64-64 j9vmap6423-20071007 (JIT enabled)

2) 架構資訊

各節點屬於單獨被管節點，未在同一叢集中

3) 連線池配置

4) 故障連線池SCDS配置

2. 連線池問題

2. 1 問題描述

如上圖所示SCDS連線池，在Weblogic服務啟動後，BATCH4節點連線池不能按預期配置的初始建立80個連線。服務執行一段時候間後Current Capacity容量保持在40左右，執行一段時間後部分業務不可用，必須重啟服務。檢視中介軟體後臺日誌資訊，發現日誌中存在大量與連線池錯誤有關日誌。

2.2 錯誤日誌分析

1）網路閃斷問題

####<2014-8-23 上午01時41分37秒 GMT+08:00> <Error> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1408729297399> <BEA-001112> <Test "SELECT 1 FROM DUAL" set up for pool "SCWWDS4"

 failed with exception: "java.sql.SQLException: Io 異常: Connection reset".> 

####<2014-9-3 上午02時52分43秒 GMT+08:00> <Error> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1409683963815> <BEA-001112> <Test "SELECT 1 FROM DUAL" set up for pool "SCWWDS4" failed with exception: "java.sql.SQLException: Io 異常: Connection reset".>

####<2014-9-5 上午12時55分00秒 GMT+08:00> <Error> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <Sched_cpees_Worker-32> <<anonymous>> <> <> <1409849700178> <BEA-001112> <Test "SELECT 1 FROM DUAL" set up for pool "SCWWDS4" failed with exception: "java.sql.SQLException: Io 異常: Connection reset".> 

####<2014-9-13 上午01時33分30秒 GMT+08:00> <Error> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1410543210281> <BEA-001112> <Test "SELECT 1 FROM DUAL" set up for pool "SCWWDS4" failed with exception: "java.sql.SQLException: Io 異常: Connection reset".> 

以上日誌說明BATH4節點所使用的SCWWDS4連線池與資料庫之間網路物理連線有閃斷問題，可能存在網路不穩定狀況，建議網路工程師在近期檢查網路狀況。

2）物理連線關閉

Weblogic Server日誌：

####<2014-9-5 上午02時10分12秒 GMT+08:00> <Info> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <Thread-2574368> <<anonymous>> <> <> <1409854212313> <BEA-001128> <Connection for pool "SCDS" closed.> 

在Weblogic Server日誌中可以觀察到大量的Connection for pool "SCDS" closed資訊，表示系統在某一時刻會批量關閉一批連線，一般斷掉物理連線會這麼做（WebLogic 配置池收縮也會這麼做，如果未配置的話預設為900s檢查一次，從您的配置檔案發現未配置池收縮）。從執行緒名稱看，是應用程式的執行緒關閉了連線。且在應用日誌發現有大量如下日誌資訊：

972102: 0E9F01ITRG2C594F: 220809998 INFO cn.gwssi.common.dao.ds.source.DBController(close:321) - [gwssi] 執行緒[972102]關閉資料庫連線；連線時間:2014/09/15 08:30:20 143；關閉時間:2014/09/15 08:30:20 147

建議讓開發人員檢查程式，為什麼要關閉物理連線。一般我們不建議應用程式直接管理連線池的連線，這些都是Weblogic自身管理的，不然容易造成混亂。應用程式只在需要時從連線池中獲取連線，使用完成後呼叫connection.close()方法把連線還給池即可。（這裡的close不是關閉連線物理連線，而是把連線還給連線池，以便應用程式再使用）

3）連線池引數不合理

Weblogic Server日誌：

#####<2014-9-15 上午09時10分58秒 GMT+08:00> <Info> <Common> <nw_cpees_pichuli_3> <BATCH4> <Thread-973306> <<anonymous>> <> <> <1410743458081> <BEA-000628> <Created "1" resources for pool "SCDS", out of which "1" are available and "0" are unavailable.> 

在Weblogic Server日誌中可以觀察到大量的上述資訊，表示系統業務高峰期時大量建立連線，另與現場工程師溝通發現出現過Reached maximum capacity of pool資訊。可以看出當前連線池引數設定稍有不合理之處，建議將連線池最大值調整為120，步增長調整為5。

4）連線洩露

Weblogic Server日誌：

####<2014-9-12 上午11時39分41秒 GMT+08:00> <Warning> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <[ACTIVE] ExecuteThread: '6' for queue: 'weblogic.kernel.Default (self-

tuning)'> <<WLS Kernel>> <> <> <1410493181108> <BEA-001153> <Forcibly releasing inactive connection 

"weblog[email protected]3c296c5" back into the connection pool "SCDS", currently reserved by: java.lang.Exception

at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:291)

at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:314)

at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:292)

at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:425)

at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:316)

at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:93)

at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:106)

at weblogic.jdbc.pool.Driver.connect(Driver.java:149)

at weblogic.jdbc.jts.Driver.getNonTxConnection(Driver.java:642)

at weblogic.jdbc.jts.Driver.connect(Driver.java:124)

at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:339)

at cn.gwssi.plugin.dao.datasource.db.ConnectSourceImpl.getConnection(ConnectSourceImpl.java:166)

at cn.gwssi.common.dao.ds.UserConnectionPool.getConnection(UserConnectionPool.java:68)

at cn.gwssi.common.dao.ds.ConnectFactory.getConnection(ConnectFactory.java:73)

at cn.gwssi.plugin.dao.datasource.table.TableImpl.getConnection(TableImpl.java:105)

at cn.gwssi.common.dao.func.RegisterSqlRowset.executeSql(RegisterSqlRowset.java:58)

at cn.gwssi.common.dao.iface.DaoFunction.execute(DaoFunction.java:293)

at cn.gwssi.common.dao.BaseTable.invokeRegisterMethod(BaseTable.java:567)

at cn.gwssi.common.dao.BaseTable.executeFunction(BaseTable.java:502)

at cn.gwssi.app.codemap.cache.method.MethodCodeDefine.loadCodeData(MethodCodeDefine.java:234)

at cn.gwssi.app.codemap.cache.method.MethodCodeDefine.getCodeSet(MethodCodeDefine.java:204)

at cn.gwssi.app.codemap.txn.TxnCodeList.txnFFFF02(TxnCodeList.java:58)

at cn.gwssi.common.txn.service.TxnBrokerApp.getValueListFromDao(TxnBrokerApp.java:272)

at cn.gwssi.common.web.proxy.application.PojoClient.getValueListFromDao(PojoClient.java:101)

at cn.gwssi.common.web.proxy.application.ApplicationTransactionClient.getValueListFromDao(ApplicationTransactionClient.java:217)

at cn.gwssi.common.web.proxy.TxnClient.getValueListFromDao(TxnClient.java:455)

at cn.gwssi.common.web.tag.util.ListData.getValueListFromDao(ListData.java:369)

at cn.gwssi.common.web.tag.util.ListData.getParamList(ListData.java:243)

at cn.gwssi.common.web.tag.export.FieldTagDefinition.getValueList(FieldTagDefinition.java:436)

at cn.gwssi.common.web.tag.export.FieldTagDefinition.getValueList(FieldTagDefinition.java:413)

at cn.gwssi.common.web.tag.util.BaseFieldTag.getValueList(BaseFieldTag.java:282)

at cn.gwssi.common.web.tag.select.SelectFieldTag.prepareOptions(SelectFieldTag.java:496)

at cn.gwssi.common.web.tag.select.SelectFieldTag.prepareListData(SelectFieldTag.java:407)

at cn.gwssi.common.web.tag.select.SelectFieldTag.prepareElement_in(SelectFieldTag.java:356)

at cn.gwssi.common.web.tag.util.BaseFieldTag.prepareElement(BaseFieldTag.java:749)

at cn.gwssi.common.web.tag.theme.BlockTheme.prepareField(BlockTheme.java:316)

at cn.gwssi.common.web.tag.frame.GblockTag.prepareField(GblockTag.java:620)

at cn.gwssi.common.web.tag.frame.GblockTag.createField(GblockTag.java:551)

at cn.gwssi.common.web.tag.util.BaseFieldTag.createElement(BaseFieldTag.java:777)

at cn.gwssi.common.web.tag.select.SelectFieldTag.doEndTag(SelectFieldTag.java:375)

at jsp_servlet._app._15_dwfw._rcgz._cepct.__query_45_tzscx._jsp__tag8(__query_45_tzscx.java:538)

at jsp_servlet._app._15_dwfw._rcgz._cepct.__query_45_tzscx._jsp__tag5(__query_45_tzscx.java:412)

at jsp_servlet._app._15_dwfw._rcgz._cepct.__query_45_tzscx._jsp__tag4(__query_45_tzscx.java:346)

at jsp_servlet._app._15_dwfw._rcgz._cepct.__query_45_tzscx._jsp__tag1(__query_45_tzscx.java:241)

at jsp_servlet._app._15_dwfw._rcgz._cepct.__query_45_tzscx._jsp__tag0(__query_45_tzscx.java:192)

at jsp_servlet._app._15_dwfw._rcgz._cepct.__query_45_tzscx._jspService(__query_45_tzscx.java:155)

at weblogic.servlet.jsp.JspBase.service(JspBase.java:34)

at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:226)

at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:124)

at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:283)

at weblogic.servlet.internal.ServletStubImpl.onAddToMapException(ServletStubImpl.java:394)

at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:309)

at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:26)

at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42)

at cn.gwssi.filter.SecurityFilter.doFilter(SecurityFilter.java:35)

at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42)

at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3393)

at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)

at weblogic.security.service.SecurityManager.runAs(Unknown Source)

at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2140)

at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2046)

at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1366)

at weblogic.work.ExecuteThread.execute(ExecuteThread.java:200)

at weblogic.work.ExecuteThread.run(ExecuteThread.java:172)

.>

####<2014-8-20 下午10時02分55秒 GMT+08:00> <Warning> <JDBC> <nw_cpees_pichuli_3> <BATCH4> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-

tuning)'> <<WLS Kernel>> <> <> <1408543375817> <BEA-001153> <Forcibly releasing inactive connection 

"weblog[email protected]2f3223b" back into the connection pool "SCDS", currently reserved by: java.lang.Exception

at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:291)

at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:314)

at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:292)

at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:425)

at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:316)

at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:93)

at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:106)

at weblogic.jdbc.pool.Driver.connect(Driver.java:149)

at weblogic.jdbc.jts.Driver.getNonTxConnection(Driver.java:642)

at weblogic.jdbc.jts.Driver.connect(Driver.java:124)

at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:339)

at cn.gwssi.plugin.dao.datasource.db.ConnectSourceImpl.getConnection(ConnectSourceImpl.java:166)

at cn.gwssi.common.dao.ds.UserConnectionPool.getConnection(UserConnectionPool.java:68)

at cn.gwssi.common.dao.ds.ConnectFactory.getConnection(ConnectFactory.java:73)

at cn.gwssi.common.dao.ds.ConnectFactory.getConnection(ConnectFactory.java:52)

at cn.gwssi.common.ioc.component.DefaultDBConnection.getConnection(DefaultDBConnection.java:74)

at cn.gwssi.common.ioc.component.DefaultDBConnection.getConnection(DefaultDBConnection.java:91)

at cn.gwssi.common.dao.db.DBAccessor.getConnection(DBAccessor.java:64)

at cn.gwssi.common.dao.db.DBWriter.executeUpdate(DBWriter.java:51)

at cn.gwssi.common.dao.impl.BaseDAO.executeUpdate(BaseDAO.java:65)

at cn.gwssi.common.dao.impl.GWDAO.execute(GWDAO.java:42)

at cn.gwssi.common.scheduler.ScheduleLog.startLog(ScheduleLog.java:134)

at cn.gwssi.common.scheduler.AbstractStatefulJob.beginTracer(AbstractStatefulJob.java:72)

at cn.gwssi.common.scheduler.AbstractStatefulJob.execute(AbstractStatefulJob.java:30)

at org.quartz.core.JobRunShell.run(JobRunShell.java:203)

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)

.> 

從上述日誌中可以看出，當前應用存在連線洩露。對該問題Oracle官方文件 （ID 1329416.1）對上述問題作出了具體解釋，描述如下：

WebLogic Server JDBC Connections Being Forcibly Released with Error BEA-001153: Forcibly releasing inactive connection (文件 ID 1329416.1)

問題原因及解決辦法:

根據Oracle官方解釋，造成該類問題主要原因為：業務系統程式碼程式獲取資料庫連線，當完成業務處理後，沒有使用程式碼顯式地對該連線進行關閉（即還回池中，並非關閉物理連線），從而導致分配出去的連線不能回收到連線池中進行重用，最後引發資料庫連線不足，應用出現無法使用或響應緩慢的問題。建議開發人員檢查上述紅色標註程式碼的業務主線，將呼叫連線的程式碼編寫finally語句塊進行關閉處理。

5）連線池被Disabled

12493: null: 220830934 ERROR $plugin.dao.datasource.connect.oracle.OracleConnection.getTxnException  445 - gwssi==>Connection has been administratively disabled. Try later.

java.sql.SQLException: Connection has been administratively disabled. Try later.

at cn.gwssi.plugin.dao.datasource.connect.oracle.OracleConnection.getTxnException(OracleConnection.java:471)

at cn.gwssi.common.dao.ds.source.DBController.getStatement(DBController.java:390)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.DbHelper.executeRowSet(Unknown Source)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.ValidateForSFRT.getFeiYongZlmcBydm(Unknown Source)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.ValidateForSFRT.preCheckAndGetPreCondition(Unknown Source)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.BatchUseFeeForSFRT.useFeeRealTime(BatchUseFeeForSFRT.java:49)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.ScanFeeRealTime.txnScanFeeRTime(ScanFeeRealTime.java:34)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.ScanFeeRealTimeService.__callService(Unknown Source)

at cn.gwssi.cpees.d_sf.xml.importfeerealtime.ScanFeeRealTimeService.__doService(Unknown Source)

at cn.gwssi.common.txn.service.Step.process(Step.java:98)

at cn.gwssi.common.txn.service.Action.doService(Action.java:306)

at cn.gwssi.common.txn.service.Action.callService(Action.java:205)

at cn.gwssi.common.txn.iface.ActionUtil.callService(ActionUtil.java:57)

at cn.gwssi.common.scheduler.ControlJob.perform(ControlJob.java:69)

at cn.gwssi.common.scheduler.AbstractJob.execute(AbstractJob.java:30)

at org.quartz.core.JobRunShell.run(JobRunShell.java:203)

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)

Caused by: 

java.sql.SQLException: Connection has been administratively disabled. Try later.

at weblogic.jdbc.common.internal.ConnectionEnv.checkIfEnabled(ConnectionEnv.java:770)

at weblogic.jdbc.wrapper.PoolConnection.checkConnection(PoolConnection.java:56)

at weblogic.jdbc.wrapper.Connection.preInvocationHandler(Connection.java:83)

at weblogic.jdbc.wrapper.Connection.createStatement(Connection.java:453)

at cn.gwssi.plugin.dao.datasource.db.wrap.ConnectionX.createStatement(ConnectionX.java:43)

at cn.gwssi.common.dao.ds.source.DBController.getStatement(DBController.java:384)

... 15 more

上述日誌出現不久後，連線池被disabled，導致應用獲取不到連線，大量執行緒等待資料庫連線。見如下日誌：

weblogic.jdbc.extensions.PoolDisabledSQLException: weblogic.common.resourcepool.ResourceDisabledException: Pool SCDS is disabled, cannot allocate resources to applications..

at cn.gwssi.plugin.dao.datasource.db.ConnectSourceImpl.getConnection(ConnectSourceImpl.java:169)

at cn.gwssi.common.dao.ds.UserConnectionPool.getConnection(UserConnectionPool.java:68)

at cn.gwssi.common.dao.ds.ConnectFactory.getConnection(ConnectFactory.java:73)

at cn.gwssi.plugin.dao.datasource.table.TableImpl.getConnection(TableImpl.java:105)

at cn.gwssi.plugin.dao.datasource.table.function.prepare.PrepareFunction.getSqlClause(PrepareFunction.java:48)

at cn.gwssi.common.dao.iface.SqlMethod.getStatement(SqlMethod.java:55)

at cn.gwssi.common.dao.method.SqlInsert.getSqlStatement(SqlInsert.java:77)

at cn.gwssi.common.dao.method.SqlInsert.doService(SqlInsert.java:104)

at cn.gwssi.common.dao.method.SqlInsert.execute(SqlInsert.java:125)

at cn.gwssi.common.dao.method.SqlInsert.execute(SqlInsert.java:137)

at cn.gwssi.cpees.d_sf.sflog.TxnAsyncLog.txn04scanfeert(Unknown Source)

at cn.gwssi.cpees.d_sf.sflog.TxnAsyncLogService.__callService(Unknown Source)

at cn.gwssi.cpees.d_sf.sflog.TxnAsyncLogService.__doService(Unknown Source)

at cn.gwssi.common.txn.service.Step.process(Step.java:98)

at cn.gwssi.common.txn.service.Action.doService(Action.java:306)

at cn.gwssi.common.txn.service.Action.callService(Action.java:205)

at cn.gwssi.plugin.jms.JmsTransaction.process1(JmsTransaction.java:174)

at cn.gwssi.plugin.jms.JmsTransaction.process(JmsTransaction.java:106)

at cn.gwssi.plugin.jms.AsyncService$Worker.run(AsyncService.java:91)

at java.lang.Thread.run(Thread.java:810)

Caused by: 

weblogic.jdbc.extensions.PoolDisabledSQLException: weblogic.common.resourcepool.ResourceDisabledException: Pool SCDS is disabled, cannot allocate resources to applications..

at weblogic.jdbc.common.internal.JDBCUtil.wrapAndThrowResourceException(JDBCUtil.java:241)

at weblogic.jdbc.pool.Driver.connect(Driver.java:160)

at weblogic.jdbc.jts.Driver.getNonTxConnection(Driver.java:642)

at weblogic.jdbc.jts.Driver.connect(Driver.java:124)

at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:339)

at cn.gwssi.plugin.dao.datasource.db.ConnectSourceImpl.getConnection(ConnectSourceImpl.java:166)

... 19 more

該問題屬於Weblogic 在該版本已知bug，官方文件

java.sql.SQLException: Connection has been administratively disabled. Try later. (文件 ID 1211143.1) 對問題進行了詳細的描述

問題版本與症狀：

引起的原因：

引起該問題有兩種原因：

（1）資料庫不可用導致

（2）Weblogic bug導致

針對cause1，建議資料庫工程師檢查資料庫，是否存在較為嚴重問題導致資料庫中介軟體連線中斷。

針對Cause2、Cause3建議為該版本Weblogic打Patch 8174835、 Patch 8188896補丁。

根據Oracle官方解釋及日誌表象，建議後續從以下幾方面著手（後續操作建議按給出的先後順序操作）。

（1）建議網路工程師排查網路，在近期是否有網路不穩定現象。

（2）建議讓開發人員檢查程式，不建議應用程式直接管理連線池的連線。

（3）建議資料庫工程師檢查資料庫，排查資料庫是否存在異常，是否存在較為嚴重問題導致資料庫中介軟體連線中斷。

（4）當前應用程式再使用SCDS資料來源時存在連線洩露，建議開發商檢查程式碼，編寫finnally語句塊進行處理。

（5）找到應用洩露點處理以後，根據Oracle官方文件ID 1211143.1建議為當前版本Weblogic打Patch 8174835、 Patch 8188896補丁。

（6）當前步增長值過小，業務高峰期時容易造成大量執行緒等待資料庫連線，建議打補丁後先將步增長值由原來1個調整為5個。後續觀察連線池使用情況，通過中介軟體控制檯Service 》Data Source 》SCDS 》Monitor觀察Active Connections High Count 屬性，是否存在超過最大配置80現象，如若出現，勢必會造成連線等待，建議由原來80增長為120.