MySQL/Hibernate - 我如何调试不断下降的 MySQL 池连接？

Posted

技术标签:

【中文标题】MySQL/Hibernate - 我如何调试不断下降的 MySQL 池连接？【英文标题】：MySQL/Hibernate - How do I debug a MySQL pooled connection that keeps dropping? 【发布时间】：2015-12-15 18:10:41 【问题描述】：

几个月来，我的 Web 应用程序运行顺利，但在过去的一两周内，它不断断开与 mysql 服务器的连接。我不是 DBA，不知道如何调试。

这是我所知道的：

    连接似乎每隔几个小时就会断开一次。有时在白天，但总是在夜间。 我的实验室有一台 MySQL 服务器，用于托管多个应用程序的数据库。 目前，我们有 46 个连接到 MySQL 服务器。 据我所知，没有其他应用程序遇到此问题。 我的应用程序使用与另一个应用程序相同的堆栈、配置甚至代码来连接到数据库 - 这个另一个应用程序每天支持大约 200 个用户，并且自 2013 年以来一直平稳运行。

    两个应用程序都使用 Hibernate ORM；这是我所知道的唯一配置：

    <!-- TomcatJDBCConnectionProvider class is common to both applications -->
<property name="hibernate.connection.provider_class">org.hibernate.connection.TomcatJDBCConnectionProvider</property>
<property name="hibernate.dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="hibernate.connection.pool_size">5</property>
<property name="hibernate.current_session_context_class">thread</property>
<property name="hibernate.tomcatJdbcPool.validationQuery">SELECT 1</property>
<property name="hibernate.tomcatJdbcPool.testOnBorrow">true</property>
<property name="hibernate.enable_lazy_load_no_trans">true</property>

    这个问题大约是在有人试图使用应用程序的 RESTful API 下载我们的数据时开始的。这个用户——实际上是一个协作者——有一个小脚本迭代特定表中的每一行并请求所有元数据。

    这个问题也是在我的实验室开始提供 Coursera 大规模开放在线课程的同时开始的。我不知道这些数字是多少，但网站上的实际使用量肯定有所增加。

我知道这是一个广泛的问题，但我真的不知道如何进行调试。任何建议表示赞赏。

编辑：

挖掘其他应用程序的ServletContextListener，我发现了我的contextDestroyed 函数没有的这段代码：

// TODO: Find memory leak that requires server to be restarted after hot deploying several (3?) times.
Set<Thread> threadSet = Thread.getAllStackTraces().keySet();
for (Thread t : threadSet) 
    if (t.getName().contains("Abandoned connection cleanup thread")) 
        synchronized (t) 
            System.out.println("Forcibly stopping thread to avoid memory leak: " + t.getName());
            t.stop(); // don't complain, it works

它似乎在遍历堆栈跟踪，找到带有文本"Abandoned connection cleanup thread" 的那个并手动停止它。好像和我的问题有关？

2015 年 9 月 21 日编辑：

本周末我的申请失败了。这是昨天错误日志中的堆栈跟踪（当我相信它发生故障时）：

20-Sep-2015 14:22:18.160 SEVERE [http-apr-8080-exec-35] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [edu.mssm.pharm.maayanlab.Harmonizome.api.GeneMetadataApi] in context with path [/Harmonizome] threw exception
 org.hibernate.exception.GenericJDBCException: Could not open connection
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:304)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169)
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160)
    at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1395)
    at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:224)
    at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:545)
    at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:124)
    at org.hibernate.collection.internal.PersistentSet.iterator(PersistentSet.java:180)
    at edu.mssm.pharm.maayanlab.Harmonizome.json.serdes.GeneMetadataSerializer.serialize(GeneMetadataSerializer.java:54)
    at edu.mssm.pharm.maayanlab.Harmonizome.json.serdes.GeneMetadataSerializer.serialize(GeneMetadataSerializer.java:23)
    at com.google.gson.TreeTypeAdapter.write(TreeTypeAdapter.java:70)
    at com.google.gson.Gson.toJson(Gson.java:600)
    at com.google.gson.Gson.toJson(Gson.java:579)
    at com.google.gson.Gson.toJson(Gson.java:534)
    at edu.mssm.pharm.maayanlab.Harmonizome.api.GeneMetadataApi.doGet(GeneMetadataApi.java:65)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:622)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
    at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2440)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.tomcat.jdbc.pool.PoolExhaustedException: [http-apr-8080-exec-35] Timeout: Pool empty. Unable to fetch a connection in 30 seconds, none available[size:5; busy:5; idle:0; lastwait:30000].
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:672)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
    at org.hibernate.connection.TomcatJDBCConnectionProvider.getConnection(TomcatJDBCConnectionProvider.java:208)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297)

这是我在 MySQL 中的连接变量：

mysql>  SHOW VARIABLES LIKE '%connect%';
+-----------------------------------------------+-----------------+
| Variable_name                                 | Value           |
+-----------------------------------------------+-----------------+
| character_set_connection                      | utf8            |
| collation_connection                          | utf8_general_ci |
| connect_timeout                               | 5               |
| default_master_connection                     |                 |
| extra_max_connections                         | 1               |
| init_connect                                  |                 |
| max_connect_errors                            | 100             |
| max_connections                               | 100             |
| max_user_connections                          | 0               |
| performance_schema_session_connect_attrs_size | 512             |
+-----------------------------------------------+-----------------+

mysql>  SHOW VARIABLES LIKE '%timeout%';
+-----------------------------+----------+
| Variable_name               | Value    |
+-----------------------------+----------+
| connect_timeout             | 5        |
| deadlock_timeout_long       | 50000000 |
| deadlock_timeout_short      | 10000    |
| delayed_insert_timeout      | 300      |
| innodb_flush_log_at_timeout | 1        |
| innodb_lock_wait_timeout    | 50       |
| innodb_rollback_on_timeout  | OFF      |
| interactive_timeout         | 28800    |
| lock_wait_timeout           | 31536000 |
| net_read_timeout            | 30       |
| net_write_timeout           | 60       |
| slave_net_timeout           | 3600     |
| thread_pool_idle_timeout    | 60       |
| wait_timeout                | 28800    |
+-----------------------------+----------+

2015 年 9 月 22 日编辑：

SEVERE Tomcat 错误会导致该问题吗？我看到一个与数据库无关的关于解析日期的错误：

22-Sep-2015 10:09:53.481 SEVERE [http-apr-8080-exec-26] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [edu.mssm.pharm.maayanlab.Harmonizome.page.DatasetPage] in context with path [/Harmonizome] threw exception [javax.servlet.ServletException: javax.servlet.jsp.JspException: In &lt;parseDate&gt;, a parse locale can not be established] with root cause
 javax.servlet.jsp.JspException: In &lt;parseDate&gt;, a parse locale can not be established
    at org.apache.taglibs.standard.tag.common.fmt.ParseDateSupport.doEndTag(ParseDateSupport.java:147)

附加堆内存使用的JConsole输出：

线程使用的 JConsole 输出；它开始于 24-25 左右，一旦我开始使用该网站，它就会跃升至 34 岁。即使在关闭浏览器窗口后，它仍然存在：

2015 年 9 月 23 日编辑：

在问题开始之前我改变的一件事是我如何处理 Hibernate 事务。以前，我禁用了enable_lazy_load_no_trans（这是默认设置）。以前，我使用的是“open session in view”模式。似乎人们不喜欢视图模式中的开放会话，所以我启用了enable_lazy_load_no_trans。因此，我有这样的代码：

List<MyObjects> myObjects = null;
try 
    HibernateUtil.beginTransaction();
    myObjects = // fetch my objects from the DB
    HibernateUtil.commitTransaction();
 catch (HibernateException he) 
    HibernateUtil.rollbackTransaction();
 finally 
    HibernateUtil.close();


// render myObjects in JSP/JSTL
// this JSP may lazily load related objects

回想起来，这似乎……有问题。我不知道 Hibernate 什么时候“放开”这些对象。

【问题讨论】：

内存问题？在部署 Mysql 和 Application 的机器上部署了任何其他应用程序吗？ 我对这个连接池的实现没有经验，但我会从实现 QueryTimeoutInterceptor 开始调试：tomcat.apache.org/tomcat-7.0-doc/… @Gaurav，其他几个小应用程序正在同一台机器上运行。我们有一个集群，由于历史原因，我每次都在同一台机器上运行应用程序有一个限制，但我刚刚重新部署它可以在任何地方运行，以防一台机器出现问题。 你查看过数据库日志文件，看看是否有错误。从以下位置发布结果：SHOW VARIABLES LIKE '%connect%'; 可能是内存泄漏。请参阅我的最新编辑。 @BerndBuffen，我也会考虑你的建议。 【参考方案1】：

从您提供的堆栈跟踪中，我可以得出一个结论：您只是用完了连接。

这可能是由长时间运行的事务引起的，可能是由于查询速度慢或应用程序事务边界不正确。

我建议你开始使用FlexyPool，它支持Tomcat DBCP，并更好地了解连接和事务的使用。 FlexyPool 提供了许多您可能感兴趣的histograms，例如连接获取时间和租用时间。

为了安全起见，请检查 MySQL 驱动程序版本，看看您是否在过时的库上运行。

【讨论】：

我会查看 FlexyPool 和那篇文章。请查看我在 2015 年 9 月 23 日的编辑，如果我的对象延迟加载似乎有问题，请告诉我。 使用“在视图中打开会话”并不是一个好主意，因为事务必须等待响应发送到客户端才能提交。事务越长，它对连接池施加的压力就越大，因为连接的租用间隔会更长。 这可能是个坏主意，我可以在未来寻找替代方案，但我删除了enable_lazy_load_no_trans 并重新实现了视图模式中的打开会话。我的应用程序已经运行了 5 天而没有数据库连接超时。我相当有信心我们很清楚。我肯定会研究 FlexyPool — 那篇文章看起来很有用 — 如果您有关于 open session 的干净替代方案的建议，我会很高兴听到它。【参考方案2】：

您的连接池似乎无法在超时时间内返回到 Hibernate 的空闲连接。发生这种情况是因为您的应用程序有很长的事务或事务死锁。您可以尝试以下选项来修复该错误。

    在下一行更改您的连接池大小

    &lt;property name="hibernate.connection.pool_size"&gt;5&lt;/property&gt;

使池大小约为 10 并进行测试。您应该密切关注与数据库的连接数。如果超过mysql数据库连接限制，请更改mysql服务器的max_connections并继续测试。

    使用另一个连接池。我推荐使用 apache commons dbcp2。 dbcp2的maven依赖如下。

    <dependency> <groupId>org.apache.commons</groupId> <artifactId>commons-dbcp2</artifactId> <version>2.1</version> </dependency>

将 dbcp2 添加到您的 POM 中，然后使用您的应用程序配置 dbcp2。

如果这是您的应用程序只有长事务的解决方案。有时它可以最大限度地减少这种情况的发生，如果它仍然发生，那么您的应用程序肯定会有事务死锁。因此，您必须确定您的代码可能存在哪些问题。

还有其他替代解决方案，例如将等待超时更改为更高的值。但这对您的应用程序性能不利，并且对事务死锁没有任何意义。最后，您应该记住在您的进一步开发中关心事务管理和数据库结构，以获得更好的数据库性能。

【讨论】：

您是否使用更大的连接池进行测试？现在发生了什么？ 我不想重新启动，因为自从我删除 enable_lazy_load_no_trans 后，我的服务器一直运行顺利。见我对弗拉德的 cmets。【参考方案3】：

Hibernate 错误有点抽象，有时很难通过堆栈跟踪找到错误。我认为这可能是您的应用程序的问题，也许您在某些情况下没有正确关闭 Hibernate 连接，或者您的应用程序可能存在内存泄漏。

您是否尝试过使用 JDK 中的 jconsole 监控应用程序？

您可以在 Tomcat 配置控制台中的 Java 参数中进行设置（我假设您使用的是 Tomcat），以启用 jconsole

-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=8086
-Dcom.sun.management.jmxremote.ssl=false
-Dcom.sun.management.jmxremote.authenticate=false

然后连接到远程进程例如

localhost:8086

并在执行使应用程序停止的操作时观察线程。

编辑

如果您不使用 Tomcat 并且您在 Windows 环境中运行应用程序，您可以使用 Process Explorer 监控线程并监控您的应用程序。

【讨论】：

哇。我从来没有见过这个。在 OS X 上使用 Eclipse，我将这些参数放在 Open launch configuration &gt; Arguments 中。端口应该用于我的应用程序？ 我添加了内存使用情况的截图。 您必须设置一个未使用的端口，才能连接到 jconsole。但似乎你已经设法连接了:) 你能打印线程而不是内存吗？打印线程，而不是在您认为有问题的地方执行一些随机操作，然后再打印。并分享两者 我添加了我的应用程序线程使用情况的屏幕截图。请注意，这一切现在都在我的本地机器上。 如果您打开应用程序的另一个实例并进行更多导航，它会创建更多线程（不会关闭）还是会在 30 年代继续？尝试导航更长的时间并执行更多操作。你做得越多越好

以上是关于MySQL/Hibernate - 我如何调试不断下降的 MySQL 池连接？的主要内容，如果未能解决你的问题，请参考以下文章

如何让我的 Visual Studio 在没有调试程序的情况下运行不断扩大 RAM 使用量直到 RAM 已满，甚至将 SSD 用作“RAM”？

如何在 MySQL 列中保存 DATE

Android调试器不断断开连接

不断获取...DeviceMonitor] 启动监控失败

JPA、MySQL、Hibernate 和 Maven 骨架

Spring、Spring Security、JPA、MySQL、Hibernate 配置