IBM 自由数据源花费太多时间（在 AWS RDS 故障转移之后）
IBM liberty datasource taking too much time (after AWS RDS failover)
我已经使用如下所示的 oracle 连接详细信息配置了数据源。
<dataSource id="auditLogDatasource" jndiName="jdbc/audit_log" type="javax.sql.DataSource" validationTimeout="10s">
<jdbcDriver libraryRef="OracleLib"/>
<properties.oracle description="main db pipe" URL="jdbc:oracle:thin://@localhost:1686/mkapp"
password="test" user="test"/>
<connectionManager id="ConnectionManager"
maxPoolSize="30" minPoolSize="1" purgePolicy="FailingConnectionOnly" />
</dataSource>
Java代码
@Resource(lookup = "jdbc/audit_log")
public void setDataSource(DataSource dataSource) {
if (this.dataSource == null) {
this.dataSource = dataSource;
}
}
public void store(@Observes AuditRecord auditRecord) {
Connection con = null;
PreparedStatement preparedStatement = null;
try {
log.info("DB connection requested");
con = this.dataSource.getConnection();
preparedStatement = con.prepareStatement(INSERT_QUERY);
int index = 1;
preparedStatement.setString(index++, auditRecord.getAction());
preparedStatement.setString(index++, auditRecord.getUserInitiating());
preparedStatement.setString(index++, auditRecord.getUserAffected());
preparedStatement.setString(index++, auditRecord.getAdditionalInfo());
preparedStatement.setTimestamp(index++, new Timestamp(auditRecord.getCreateTime().getTime()));
preparedStatement.setString(index++, auditRecord.getServer());
preparedStatement.executeUpdate();
log.info("DB record added");
} catch (Exception e) {
log.error(e.getMessage(), e);
} finally {
if (preparedStatement != null) {
try {
preparedStatement.close();
} catch (SQLException e) {
log.error(e.getMessage(), e);
}
}
if (con != null) {
try {
con.close();
} catch (SQLException e) {
log.error(e.getMessage(), e);
}
}
}
}
最初一切正常，大部分情况下我只看到 1 个空闲连接数。
But once I trigger AWS RDS failover (Reboot with failover) server
taking too much time to discard the invalid connection from pool & creating new connection.
2019/11/15 17:31:28.571 [Default Executor-thread-60] INFO dao.AuditDao : DB connection requested
2019/11/15 17:47:03.741 [Default Executor-thread-60] INFO dao.AuditDao : DB record added
16 分钟后 message.log 出错
[ERROR ] J2CA0081E: Method destroy failed while trying to execute method destroy on ManagedConnection WSRdbManagedConnectionImpl@10e0477e from resource No longer available. Caught exception: com.ibm.ws.rsadapter.exceptions.DataStoreAdapterException: DSRA0080E: An exception was received by the Data Store Adapter. See original exception message: {0}. with SQL State : 08000 SQL Code : 17410
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.destroy(WSRdbManagedConnectionImpl.java:2513)
at [internal classes]
at com.test.auth.dao.AuditDao.store(AuditDao.java:38)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
at [internal classes]
at com.test.auth.AuthHomeServlet.audit(AuthHomeServlet.java:72)
at com.test.auth.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1255)
at [internal classes]
at com.test.auth.UserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
at [internal classes]
Caused by: java.sql.SQLRecoverableException: No more data to read from socket DSRA0010E: SQL State = 08000, Error Code = 17,410
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1157)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:350)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)
at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:61)
at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:574)
at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:4011)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.destroy(WSRdbManagedConnectionImpl.java:2508)
... 17 more
有什么方法可以配置连接关闭超时吗？虽然我配置了 validationTimeout 似乎不起作用。
Liberty version: 17.0.0.4
Database product version : Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
JDBC driver version : 12.1.0.2.0
Driver lib: ojdbc6.jar / ojdbc7.jar
是否与DNS问题有关？谁能指出我正确的方向...
更新
这是我从线程转储中得到的
Default Executor-thread-29" #87 daemon prio=5 os_prio=31 tid=0x00007fa06793d800 nid=0x13d03 waiting for monitor entry [0x0000700012743000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jdbc.driver.PhysicalConnection.isProxySession(PhysicalConnection.java:4398)
- waiting to lock <0x00000007bd6d0900> (a oracle.jdbc.driver.T4CConnection)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ws.rsadapter.impl.OracleHelper.doConnectionCleanup(OracleHelper.java:354)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanupStates(WSRdbManagedConnectionImpl.java:2847)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanup(WSRdbManagedConnectionImpl.java:2774)
at com.ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1541)
at com.ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:459)
at com.ibm.ejs.j2c.PoolManager.reserve(PoolManager.java:1602)
at com.ibm.ejs.j2c.ConnectionManager.allocateMCWrapper(ConnectionManager.java:581)
at com.ibm.ejs.j2c.ConnectionManager.allocateConnection(ConnectionManager.java:314)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:138)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:112)
at test.dao.AuditDao.store(AuditDao.java:38)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:78)
at org.jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:129)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:299)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:277)
at org.jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:255)
at org.jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:269)
at org.jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:258)
at org.jboss.weld.event.EventImpl.fire(EventImpl.java:92)
at test.AuthHomeServlet.audit(AuthHomeServlet.java:72)
at test.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1230)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:729)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:426)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:182)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:93)
at test.MkidUserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:90)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:1001)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1139)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1010)
at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:75)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:938)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.run(DynamicVirtualHost.java:279)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1136)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:417)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:376)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:548)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:482)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:347)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:318)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.determineNextChannel(SSLConnectionLink.java:1077)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink$MyReadCompletedCallback.complete(SSLConnectionLink.java:656)
at com.ibm.ws.channel.ssl.internal.SSLReadServiceContext$SSLReadCompletedCallback.complete(SSLReadServiceContext.java:1803)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:503)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:573)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:954)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1043)
at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:239)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- <0x00000007822c8b38> (a java.util.concurrent.ThreadPoolExecutor$Worker)
来自requestTiming功能
[11/17/19 20:03:22:442 AEDT] 000000ee com.ibm.ws.request.timing.manager.SlowRequestManager W TRAS0112W: Request AAAcI1bXZti_AAAAAAAAAAD has been running on thread 000000df for at least 30016.328ms. The following stack trace shows what this thread is currently running.
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:95)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:508)
at com.ibm.ws.rsadapter.impl.OracleHelper.doConnectionCleanup(OracleHelper.java:355)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanupStates(WSRdbManagedConnectionImpl.java:2752)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanup(WSRdbManagedConnectionImpl.java:2679)
at com.ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1492)
at com.ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:444)
at com.ibm.ejs.j2c.PoolManager.reserve(PoolManager.java:1543)
at com.ibm.ejs.j2c.ConnectionManager.allocateMCWrapper(ConnectionManager.java:547)
at com.ibm.ejs.j2c.ConnectionManager.allocateConnection(ConnectionManager.java:283)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:143)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:116)
at com.testt.auth.dao.AuditDao.store(AuditDao.java:37)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:95)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:508)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:78)
at org.jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:129)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:299)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:277)
at org.jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:255)
at org.jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:269)
at org.jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:258)
at org.jboss.weld.event.EventImpl.fire(EventImpl.java:91)
at com.test.auth.AuthHomeServlet.audit(AuthHomeServlet.java:72)
at com.test.auth.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1255)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:743)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:440)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:147)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
at com.test.auth.MkidUserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:86)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:995)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1124)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1004)
at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:76)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:926)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.run(DynamicVirtualHost.java:279)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:957)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:357)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:316)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:499)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:433)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:313)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:284)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.determineNextChannel(SSLConnectionLink.java:1029)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.readyInboundPostHandshake(SSLConnectionLink.java:695)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink$MyHandshakeCompletedCallback.complete(SSLConnectionLink.java:383)
at com.ibm.ws.channel.ssl.internal.SSLUtils.handleHandshake(SSLUtils.java:947)
at com.ibm.ws.channel.ssl.internal.SSLHandshakeIOCallback.complete(SSLHandshakeIOCallback.java:85)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:501)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:571)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:926)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1015)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.lang.Thread.run(Thread.java:785)
The following table shows the events that have run during this request.
Duration Operation
30018.682ms + websphere.servlet.service | auth | authHomeServlet
虽然最终报告的错误是在Connection.close，但这并不一定意味着关闭操作一直在花费时间。几个thread dumps captured during the interval could help show where the delay is, if you are able to collect that. You will also want to consider the validationTimeout, which you have configured to 10 seconds. validationTimeout="10s". This value doesn't impact the close operation, but instead determines the timeout value that is supplied to the Connection.isValid(timeout)操作，用来检查连接的有效性。通过指定 10 秒的值，您为 JDBC 驱动程序提供最多 10 秒的时间来确定连接是否仍然有效。您可以通过减小此值或完全从配置中消除来减少延迟。
切换到 Oracle UCP 后，由于连接验证超时（15 秒），此问题消失了。我在 Openliberty github 上发布了这个问题，希望它会在未来的版本中得到修复。
我已经使用如下所示的 oracle 连接详细信息配置了数据源。
<dataSource id="auditLogDatasource" jndiName="jdbc/audit_log" type="javax.sql.DataSource" validationTimeout="10s">
<jdbcDriver libraryRef="OracleLib"/>
<properties.oracle description="main db pipe" URL="jdbc:oracle:thin://@localhost:1686/mkapp"
password="test" user="test"/>
<connectionManager id="ConnectionManager"
maxPoolSize="30" minPoolSize="1" purgePolicy="FailingConnectionOnly" />
</dataSource>
Java代码
@Resource(lookup = "jdbc/audit_log")
public void setDataSource(DataSource dataSource) {
if (this.dataSource == null) {
this.dataSource = dataSource;
}
}
public void store(@Observes AuditRecord auditRecord) {
Connection con = null;
PreparedStatement preparedStatement = null;
try {
log.info("DB connection requested");
con = this.dataSource.getConnection();
preparedStatement = con.prepareStatement(INSERT_QUERY);
int index = 1;
preparedStatement.setString(index++, auditRecord.getAction());
preparedStatement.setString(index++, auditRecord.getUserInitiating());
preparedStatement.setString(index++, auditRecord.getUserAffected());
preparedStatement.setString(index++, auditRecord.getAdditionalInfo());
preparedStatement.setTimestamp(index++, new Timestamp(auditRecord.getCreateTime().getTime()));
preparedStatement.setString(index++, auditRecord.getServer());
preparedStatement.executeUpdate();
log.info("DB record added");
} catch (Exception e) {
log.error(e.getMessage(), e);
} finally {
if (preparedStatement != null) {
try {
preparedStatement.close();
} catch (SQLException e) {
log.error(e.getMessage(), e);
}
}
if (con != null) {
try {
con.close();
} catch (SQLException e) {
log.error(e.getMessage(), e);
}
}
}
}
最初一切正常，大部分情况下我只看到 1 个空闲连接数。
But once I trigger AWS RDS failover (Reboot with failover) server taking too much time to discard the invalid connection from pool & creating new connection.
2019/11/15 17:31:28.571 [Default Executor-thread-60] INFO dao.AuditDao : DB connection requested
2019/11/15 17:47:03.741 [Default Executor-thread-60] INFO dao.AuditDao : DB record added
16 分钟后 message.log 出错
[ERROR ] J2CA0081E: Method destroy failed while trying to execute method destroy on ManagedConnection WSRdbManagedConnectionImpl@10e0477e from resource No longer available. Caught exception: com.ibm.ws.rsadapter.exceptions.DataStoreAdapterException: DSRA0080E: An exception was received by the Data Store Adapter. See original exception message: {0}. with SQL State : 08000 SQL Code : 17410
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.destroy(WSRdbManagedConnectionImpl.java:2513)
at [internal classes]
at com.test.auth.dao.AuditDao.store(AuditDao.java:38)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
at [internal classes]
at com.test.auth.AuthHomeServlet.audit(AuthHomeServlet.java:72)
at com.test.auth.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1255)
at [internal classes]
at com.test.auth.UserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
at [internal classes]
Caused by: java.sql.SQLRecoverableException: No more data to read from socket DSRA0010E: SQL State = 08000, Error Code = 17,410
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1157)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:350)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)
at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:61)
at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:574)
at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:4011)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.destroy(WSRdbManagedConnectionImpl.java:2508)
... 17 more
有什么方法可以配置连接关闭超时吗？虽然我配置了 validationTimeout 似乎不起作用。
Liberty version: 17.0.0.4
Database product version : Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
JDBC driver version : 12.1.0.2.0
Driver lib: ojdbc6.jar / ojdbc7.jar
是否与DNS问题有关？谁能指出我正确的方向...
更新
这是我从线程转储中得到的
Default Executor-thread-29" #87 daemon prio=5 os_prio=31 tid=0x00007fa06793d800 nid=0x13d03 waiting for monitor entry [0x0000700012743000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jdbc.driver.PhysicalConnection.isProxySession(PhysicalConnection.java:4398)
- waiting to lock <0x00000007bd6d0900> (a oracle.jdbc.driver.T4CConnection)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ws.rsadapter.impl.OracleHelper.doConnectionCleanup(OracleHelper.java:354)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanupStates(WSRdbManagedConnectionImpl.java:2847)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanup(WSRdbManagedConnectionImpl.java:2774)
at com.ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1541)
at com.ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:459)
at com.ibm.ejs.j2c.PoolManager.reserve(PoolManager.java:1602)
at com.ibm.ejs.j2c.ConnectionManager.allocateMCWrapper(ConnectionManager.java:581)
at com.ibm.ejs.j2c.ConnectionManager.allocateConnection(ConnectionManager.java:314)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:138)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:112)
at test.dao.AuditDao.store(AuditDao.java:38)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:78)
at org.jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:129)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:299)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:277)
at org.jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:255)
at org.jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:269)
at org.jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:258)
at org.jboss.weld.event.EventImpl.fire(EventImpl.java:92)
at test.AuthHomeServlet.audit(AuthHomeServlet.java:72)
at test.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1230)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:729)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:426)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:182)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:93)
at test.MkidUserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:90)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:1001)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1139)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1010)
at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:75)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:938)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.run(DynamicVirtualHost.java:279)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1136)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:417)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:376)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:548)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:482)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:347)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:318)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.determineNextChannel(SSLConnectionLink.java:1077)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink$MyReadCompletedCallback.complete(SSLConnectionLink.java:656)
at com.ibm.ws.channel.ssl.internal.SSLReadServiceContext$SSLReadCompletedCallback.complete(SSLReadServiceContext.java:1803)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:503)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:573)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:954)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1043)
at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:239)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- <0x00000007822c8b38> (a java.util.concurrent.ThreadPoolExecutor$Worker)
来自requestTiming功能
[11/17/19 20:03:22:442 AEDT] 000000ee com.ibm.ws.request.timing.manager.SlowRequestManager W TRAS0112W: Request AAAcI1bXZti_AAAAAAAAAAD has been running on thread 000000df for at least 30016.328ms. The following stack trace shows what this thread is currently running.
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:95)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:508)
at com.ibm.ws.rsadapter.impl.OracleHelper.doConnectionCleanup(OracleHelper.java:355)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanupStates(WSRdbManagedConnectionImpl.java:2752)
at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanup(WSRdbManagedConnectionImpl.java:2679)
at com.ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1492)
at com.ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:444)
at com.ibm.ejs.j2c.PoolManager.reserve(PoolManager.java:1543)
at com.ibm.ejs.j2c.ConnectionManager.allocateMCWrapper(ConnectionManager.java:547)
at com.ibm.ejs.j2c.ConnectionManager.allocateConnection(ConnectionManager.java:283)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:143)
at com.ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:116)
at com.testt.auth.dao.AuditDao.store(AuditDao.java:37)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:95)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:508)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
at org.jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:78)
at org.jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:129)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:299)
at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:277)
at org.jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:255)
at org.jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:269)
at org.jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:258)
at org.jboss.weld.event.EventImpl.fire(EventImpl.java:91)
at com.test.auth.AuthHomeServlet.audit(AuthHomeServlet.java:72)
at com.test.auth.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1255)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:743)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:440)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:147)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
at com.test.auth.MkidUserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:86)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:995)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1124)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1004)
at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:76)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:926)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.run(DynamicVirtualHost.java:279)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:957)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:357)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:316)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:499)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:433)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:313)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:284)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.determineNextChannel(SSLConnectionLink.java:1029)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.readyInboundPostHandshake(SSLConnectionLink.java:695)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink$MyHandshakeCompletedCallback.complete(SSLConnectionLink.java:383)
at com.ibm.ws.channel.ssl.internal.SSLUtils.handleHandshake(SSLUtils.java:947)
at com.ibm.ws.channel.ssl.internal.SSLHandshakeIOCallback.complete(SSLHandshakeIOCallback.java:85)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:501)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:571)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:926)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1015)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.lang.Thread.run(Thread.java:785)
The following table shows the events that have run during this request.
Duration Operation
30018.682ms + websphere.servlet.service | auth | authHomeServlet
虽然最终报告的错误是在Connection.close，但这并不一定意味着关闭操作一直在花费时间。几个thread dumps captured during the interval could help show where the delay is, if you are able to collect that. You will also want to consider the validationTimeout, which you have configured to 10 seconds. validationTimeout="10s". This value doesn't impact the close operation, but instead determines the timeout value that is supplied to the Connection.isValid(timeout)操作，用来检查连接的有效性。通过指定 10 秒的值，您为 JDBC 驱动程序提供最多 10 秒的时间来确定连接是否仍然有效。您可以通过减小此值或完全从配置中消除来减少延迟。
切换到 Oracle UCP 后，由于连接验证超时（15 秒），此问题消失了。我在 Openliberty github 上发布了这个问题，希望它会在未来的版本中得到修复。