即使在设置 c3p0.testConnectionOnCheckout=true 之后，与 MySQL 的数据库连接也会超时

Posted 2023-02-24

【中文标题】即使在设置 c3p0.testConnectionOnCheckout=true 之后，与 MySQL 的数据库连接也会超时

【英文标题】：Database Connection to MySQL times out even after setting c3p0.testConnectionOnCheckout=true

【发布时间】：2013-01-11 08:06:48

【问题描述】：

我有一个使用 hibernate (v3.6.4) 的应用程序，连接池由 C3P0 (v0.9.1.2) 提供。

问题是，如果我进行数据库查询，如果应用程序进程（以及因此 C3P0 池）运行的时间超过 mysql wait_timeout 值，则会出现 JDBC 通信链接故障。我将 /etc/mysql/my.cnf 中的 wait_timeout 的值设置为 600 秒以测试此问题：

2013-01-27 20:08:00,088 ERROR [Thread-0] (JDBCExceptionReporter.java:234) - Communications link failure

The last packet successfully received from the server was 665,943 milliseconds ago.  The last packet sent successfully to the server was 6 milliseconds ago.
org.hibernate.exception.JDBCConnectionException: could not execute query
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:99)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.loader.Loader.doList(Loader.java:2536)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
at org.hibernate.loader.Loader.list(Loader.java:2271)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:119)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1716)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:347) 
.....
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 665,943 milliseconds ago.  The last packet sent successfully to the server was 6 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2293)
at  com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
at org.hibernate.loader.Loader.doQuery(Loader.java:802)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
at org.hibernate.loader.Loader.doList(Loader.java:2533)
... 9 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2552)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
... 22 more

2013-01-27 20:19:00,179  WARN [Thread-0] (NewPooledConnection.java:487) - [c3p0] Another error has occurred [ com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 1,326,037 milliseconds ago.  The last packet sent successfully to the server was 660,100 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem. ] which will not be reported to listeners!
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 1,326,037 milliseconds ago.  The last packet sent successfully to the server was 660,100 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3364)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1983)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2293)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
at org.hibernate.loader.Loader.doQuery(Loader.java:802)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
at org.hibernate.loader.Loader.doList(Loader.java:2533)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
at org.hibernate.loader.Loader.list(Loader.java:2271)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:119)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1716)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:347)
....
Caused by: java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(Unknown Source)
at java.net.SocketOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
at java.io.BufferedOutputStream.flush(Unknown Source)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3345)
... 20 more

这看起来像是一个常见问题，所以为了解决这个问题，我在检查了 hibernate/c3p0 文档并回答了 Stack Overflow 上已经提出的问题后尝试调整这些 hibernate/c3p0 属性：

相关的休眠属性：

<property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="hibernate.connection.url">jdbc:mysql://localhost:3306/gsui?useUnicode=true&amp;characterEncoding=UTF-8&amp;autoReconnect=true</property>

<property name="hibernate.connection.autoReconnect">true</property>

<!-- C3p0 Performance Improvements -->
<property name="hibernate.c3p0.acquire_increment">1</property>
<property name="hibernate.c3p0.idle_test_period">300</property>
<property name="hibernate.c3p0.maxConnectionAge">3600</property>
<property name="hibernate.c3p0.timeout">120</property>
<property name="hibernate.c3p0.max_size">300</property>
<property name="hibernate.c3p0.min_size">1</property>
<property name="hibernate.c3p0.max_statements">100</property>
<property name="hibernate.c3p0.preferredTestQuery">select 1;</property>

<property name="hibernate.connection.useUnicode">
    true
</property>
<property name="hibernate.connection.characterEncoding">
    UTF-8
</property>
<property name="hibernate.connection.charSet">
    UTF-8
</property>

我还在我维护的 c3p0 属性文件中将 c3p0.testConnectionOnCheckout 设置为 true：

c3p0.testConnectionOnCheckout=true

在日志中，C3P0 池通过以下消息正常初始化：

2013-01-27 19:45:04,607  INFO [main] (ConnectionProviderFactory.java:173) - Initializing connection provider: org.hibernate.connection.C3P0ConnectionProvider
2013-01-27 19:45:04,609  INFO [main] (C3P0ConnectionProvider.java:103) - C3P0 using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost:3306/gsui?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true
2013-01-27 19:45:04,610  INFO [main] (C3P0ConnectionProvider.java:104) - Connection properties: useUnicode=true, autoReconnect=true, user=root, password=****, shutdown=true, characterEncoding=UTF-8, charSet=UTF-8
2013-01-27 19:45:04,610  INFO [main] (C3P0ConnectionProvider.java:107) - autocommit mode: false
2013-01-27 19:45:04,629  INFO [main] (MLog.java:80) - MLog clients using log4j logging.
2013-01-27 19:45:04,757  INFO [main] (C3P0Registry.java:204) - Initializing c3p0-0.9.1.2 [built 21-May-2007 15:04:56; debug? true; trace: 10]
2013-01-27 19:45:04,842  INFO [main] (C3P0ConnectionProvider.java:194) - JDBC isolation level: READ_COMMITTED
2013-01-27 19:45:04,871  INFO [main] (AbstractPoolBackedDataSource.java:462) - Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@9f4a7137 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@71b9e1e9 [ acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kfsx8sz4pted1s4b69w|51f726b9, idleConnectionTestPeriod -> 300, initialPoolSize -> 1, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 3600, maxIdleTime -> 120, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 300, maxStatements -> 100, maxStatementsPerConnection -> 0, minPoolSize -> 1, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@58f45048 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> z8kfsx8sz4pted1s4b69w|454b7177, jdbcUrl -> jdbc:mysql://localhost:3306/gsui?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true, properties -> useUnicode=true, autoReconnect=true, user=******, password=******, shutdown=true, characterEncoding=UTF-8, charSet=UTF-8 ], preferredTestQuery -> select 1;, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> true, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides:  ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> z8kfsx8sz4pted1s4b69w|71ffd9f1, numHelperThreads -> 3 ]

从上面的日志中可以发现，C3P0 中 testConnectionOnCheckout=true 和 autoReconnect=true。有人可以帮我弄清楚为什么 C3P0 还是会检查超时连接吗？谢谢。

【问题讨论】：

您是否长时间保持连接或休眠会话打开？ （理想情况下，当使用连接池时，应立即签出、使用和关闭连接。但某些应用程序会保留/缓存连接。）

感谢您的快速回复；你似乎在这里赚钱。我的应用程序在我们拥有的较旧的 util 库中使用 DAO 层，位于 HQL 和 hibernate 之上。我发现基类 DAO 从定义单例 SessionFactory 并调用其“getCurrentSession()”方法的实用程序类中获取其会话对象（这看起来是问题所在）。我原本以为休眠会话只是从 C3P0 借用连接而不是连接对象本身。

我有同样的问题，我已经查看了我的代码，寻找打开但未关闭的 Session 对象，但我仍然有问题。只是为了完整起见，我发现了另一个可能有帮助的问题：***.com/questions/15752667/…。最糟糕的是，无论我在做什么复制（最明显的情况除外），开发过程中都不会出现问题。

【参考方案1】：

当我们使用 JPA 和 C3P0 进行连接池将 hibernate 升级到 4.3.x 时，我们开始遇到相同的“通信链接”问题。

这似乎是一个连接池问题，因为尽管我进行了 C3P0 设置，但连接的保留时间比数据库 wait_timeout（默认为 8 小时）长。但是，我通过更改 persistence.xml 中的休眠配置解决了这个问题：

<property name="hibernate.connection.release_mode" value="after_transaction" />

似乎休眠中的默认行为已更改为在事务后不释放连接，因此如果您使用池化，则必须明确设置此模式。

【参考方案2】：

在您的休眠配置文件中添加以下属性。我希望它会起作用。

<property name="connection.provider_class">
  org.hibernate.connection.C3P0ConnectionProvider
</property>