java - IBM liberty 数据源花费太多时间(AWS RDS 故障转移后)

Question

我已经使用 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$2.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$2.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

Answer 1

虽然最终报告的错误是在 Connection.close 上，但这并不一定意味着关闭操作是一直占用的时间。几个thread dumps如果您能够收集的话，在间隔期间捕获的数据可以帮助显示延迟在哪里。您还需要考虑validationTimeout，您已将其配置为10 秒。 validationTimeout="10s"。该值不会影响关闭操作，而是确定提供给 Connection.isValid(timeout) 的超时值。操作，用于检查连接的有效性。通过指定 10 秒值，您将给 JDBC 驱动程序最多 10 秒的时间来确定连接是否仍然有效。您可以通过减小此值或完全从配置中消除来减少延迟。