程序员最近都爱上了这个网站  程序员们快来瞅瞅吧！  it98k网:it98k.com

我正在使用 mybatis 连接到 oracle。

我的mybatis配置是：

<settings>
    <setting name="lazyLoadingEnabled" value="true" />
    <setting name="aggressiveLazyLoading" value="false" />
    <setting name="logImpl" value="${logImpl}" />
    <setting name="defaultStatementTimeout" value="10" />
</settings>
<environments default="default">
    <environment id="default">
        <transactionManager type="JDBC" />
        <dataSource type="POOLED">
            <property name="driver" value="${jdbc.driver}" />
            <property name="url" value="${jdbc.url}" />
            <property name="username" value="${jdbc.username}" />
            <property name="password" value="${jdbc.password}" />
            <property name="poolPingConnectionsNotUsedFor" value="290000"/>
            <property name="poolPingQuery" value="SELECT COUNT(*) FROM RESORT"/>
            <property name="poolPingEnabled" value="true"/>
        </dataSource>
    </environment>
</environments>

我的公开会议代码就像

SqlSession sqlSession = factory.openSession();
Object result = null;
try
{
    QueryInfoMapper mapper = sqlSession.getMapper(QueryInfoMapper.class);
    result = mapper.queryInfoFromOpera(mybatisMapping);
} finally
{
    sqlSession.close();
}

因为类的application scoped，而sqlSession不能在application scope中使用，所以我必须自己管理sqlSession。

日志是

2019-04-11 15:30:35,773 INFO [stdout]（默认任务 60）打开 JDBC 连接

2019-04-11 15:30:41,860 INFO [stdout]（默认任务 57）连接错误。无法回滚

2019-04-11 15:30:41,861 INFO [stdout]（默认任务 57）声明过期连接 962608913。

2019-04-11 15:30:41,861 INFO [stdout]（默认任务 57）从池中返回了一个错误的连接 (962608913)，获得了另一个连接。

2019-04-11 15:30:41,895 INFO [stdout]（默认任务 57）已创建连接 1812494479。

2019-04-11 15:30:41,895 INFO [stdout]（默认任务 57）在 JDBC 连接上将自动提交设置为 false [oracle.jdbc.driver.T4CConnection@6c08788f]

2019-04-11 15:30:41,895 INFO [stdout]（默认任务 57）==> 准备：SELECT TRAVEL_AGENT_NAME FROM（SELECT TRAVEL_AGENT_NAME FROM OPERA.NAME_RESERVATION WHERE RESV_NAME_ID = ?）WHERE ROWNUM = 1

2019-04-11 15:30:41,896 INFO [stdout]（默认任务 57）==> 参数：288541（字符串）

2019-04-11 15:30:41,900 INFO [stdout]（默认任务 57）<== 列：TRAVEL_AGENT_NAME

2019-04-11 15:30:41,900 INFO [stdout]（默认任务 57）<== 行：空

2019-04-11 15:30:41,900 INFO [stdout]（默认任务 57）<== 总数：1

2019-04-11 15:30:41,900 INFO [stdout]（默认任务 57）将 JDBC 连接上的自动提交重置为 true [oracle.jdbc.driver.T4CConnection@6c08788f]

2019-04-11 15:30:41 ,900 INFO [stdout]（默认任务 57）关闭 JDBC 连接[oracle.jdbc.driver.T4CConnection@6c08788f]

2019-04-11 15:31:00 ,788 INFO [stdout]（默认任务 60）连接错误。无法回滚

2019-04-11 15:31:00,788 INFO [stdout]（默认任务 60）声明过期连接 1228464923。

2019-04-11 15:31:00,788 INFO [stdout]（默认任务 60）从池中返回了一个错误的连接 (1228464923)，获得了另一个连接。

2019-04-11 15:31:00,820 INFO [stdout]（默认任务 60）已创建连接 265625885。

2019-04-11 15:31:00,820 INFO [stdout]（默认任务 60）在 JDBC 连接上将自动提交设置为 false [oracle.jdbc.driver.T4CConnection@fd5211d]

2019-04-11 15:31:00,820 INFO [stdout]（默认任务 57）将连接 1812494479 返回到池中。

看日志，根据时间戳，好像是在关闭连接时发生的（这里是事务）

但是关闭它需要 9 或 19 秒。第二个日志是“连接错误。无法回滚”。我找不到真正的原因在哪里。哪种方法需要那么多时间。这个问题不是每次都会发生，而是随机发生的。

我想设置<property name="poolMaximumActiveConnections" value="40" />增加连接。我不确定它是否有帮助。

关闭连接/交易失败的原因是什么？如何避免关闭连接/交易失败？

===========================

更新：我再次遇到这个问题，日志有些不同：

2019-04-13 15:42:31,812 INFO [stdout]（默认任务 86）打开 JDBC 连接

2019-04-13 15:42:35,493 INFO [stdout]（默认任务 62）执行 ping 查询“SELECT COUNT(*) FROM RESORT”失败：IO 错误：套接字读取超时

2019-04-13 15:42:35,493 INFO [stdout]（默认任务 62）连接 1963609369 错误：IO 错误：套接字读取超时

2019-04-13 15:42:35,493 INFO [stdout]（默认任务 62）从池中返回了一个错误的连接 (1963609369)，获得了另一个连接。

2019-04-13 15:42:35,493 INFO [stdout]（默认任务 62）已从池中检出连接 195963529。

2019-04-13 15:42:35,493 INFO [stdout]（默认任务 62）测试连接 195963529 ...

2019-04-13 15:42:54,448 INFO [stdout]（默认任务 62）执行 ping 查询“SELECT COUNT(*) FROM RESORT”失败：IO 错误：套接字读取超时

2019-04-13 15:42:54,448 INFO [stdout]（默认任务 62）连接 195963529 错误：IO 错误：套接字读取超时

2019-04-13 15:42:54,448 INFO [stdout]（默认任务 62）从池中返回了一个错误的连接 (195963529)，获得了另一个连接。

2019-04-13 15:42:54,479 INFO [stdout]（默认任务 62）已创建连接 741137137。

顺便说一句，我会将 ping sql 更改为SELECT 1 FROM DUAL. 什么可能导致此套接字读取超时？

解决方案

I can see several problems here:

1. potentially heavy ping query (as pointed by beny23)
2. long close connection operation
3. incorrect behaviour of the mybatis connection pool

You definitely need to use SELECT 1 FROM DUAL as a ping query. Otherwise you a doing some not so cheap operation on every connection open.

The long close and IO Error: Socket read timed out suggests that there is either some network connectivity issue or oracle server availability issue or both.

It makes sense to check oracle healthiness at the time when this issue happens. Does it respond to other queries at that time? What is the CPU/io/memory/swap usage etc. If the server is under very high load it may be that it does not respond in time.

Checking the issues with network connectivity is a very broad topic. The most reliable (and also complex) way I know is to capture network traffic (with tools like tcpdump or WireShark) on both ends and compare them.

Then there's an issue with mybatis connection pool.

First of all some background about how mybatis connection pool works.

One important and not obvious thing is that mybatis connection pool implementation forcefully returns connections to the pool if they are used for too long. Here's the quote from the documentation:

poolMaximumCheckoutTime – This is the amount of time that a Connection can be "checked out" of the pool before it will be forcefully returned. Default: 20000ms (i.e. 20 seconds)

It means that if the application tries to open new connection and all connections are busy then mybatis will close the oldest connection if it was in use for more than 20 seconds (by default).

It is by itself may be a very unexpected behaviour if you have some long running queries. Another and probably bigger problem is how this is implemented in mybatis. In order to grab a connection the request to rollback the transaction is done from the thread which requested new connection (In the example above thread default task-57 is holding the connection and thread default task-60 tries to get the connection from the pool).

This is the problem because oracle jdbc driver requires proper synchronization when accessing the connection from multiple threads and mybatis does not do that:

Controlled serial access to a connection, such as that provided by connection caching, is both necessary and encouraged. However, Oracle strongly discourages sharing a database connection among multiple threads. Avoid allowing multiple threads to access a connection simultaneously. If multiple threads must share a connection, use a disciplined begin-using/end-using protocol.

So this failure to synchronize access from multiple thread to the shared resource (the connection) may cause all kinds of consistency problems and I do not exclude the possibility that the problem with closing the connection is caused by the fact that connection had gotten into some inconsistent state earlier because of the lack of the synchronization.

Increasing the pool size removes this problem for the given load as the situation when the pool is exhausted does not happen (or happens less frequently).

Note that concurrency issues are very tricky to reproduce and positive synthetic test gives you virtually no guarantee. This a broad topic so recommend you to look to Goetz book for details.

I would change the connection pool implementation, namely use https://github.com/swaldman/c3p0 or https://commons.apache.org/proper/commons-dbcp/ or https://brettwooldridge.github.io/HikariCP/.