MySQL / Hibernate - 如何调试一个MySQL池连接不断丢弃? [英] MySQL/Hibernate - How do I debug a MySQL pooled connection that keeps dropping?

查看:1302
本文介绍了MySQL / Hibernate - 如何调试一个MySQL池连接不断丢弃?的处理方法,对大家解决问题具有一定的参考价值,需要的朋友们下面随着小编来一起学习吧!

问题描述

几个月来,我的网络应用程序运行顺利,但在过去一两个星期,它不断丢弃与MySQL服务器的连接。我不是一个DBA的家伙,不知道如何调试这个。



这是我知道的:


  1. 连接似乎每隔几个小时下降一次。

  2. 我的实验室有一个MySQL服务器,托管多个应用程序的数据库。

  3. 目前,

  4. 据我所知,没有其他应用程序遇到此问题。

  5. 我的应用程序使用相同的堆栈,配置,甚至连接到DB作为另一个应用程序的代码 - 这个其他应用程序每天支持大约200个用户,并且自2013年以来一直运行顺畅。

  6. 这两个应用程序都使用Hibernate ORM;这是我知道的唯一配置:

     <! -  TomcatJDBCConnectionProvider类是两个应用程序共有的> 
    < 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>


  7. 这个问题与有人试图使用应用程式的RESTful API下载我们的数据。这个用户实际上是一个协作者 - 有一个小脚本迭代特定表中的每一行,并请求所有的元数据。


  8. 问题也开始了,实验室开始提供Coursera大规模在线课程。我不知道数字是多少,但网站上的实际使用量必须跳过。

我知道是一个广泛的问题,但我真的失去了如何去调试这个。




$ b

编辑: ServletContextListener ,我发现这个位的代码,我的 contextDestroyed 函数没有:

  // TODO:查找需要在热部署几(3?)次后重新启动服务器的内存泄漏。 
Set< Thread> threadSet = Thread.getAllStackTraces()。keySet();
for(Thread t:threadSet){
if(t.getName()。contains(Abandoned connection cleanup thread)){
synchronized(t){
System。 out.println(强制停止线程以避免内存泄漏:+ t.getName());
t.stop(); // do not complain,it works
}
}
}

它似乎迭代堆栈跟踪,找到一个文本放弃的连接清除线程并手动停止它。似乎这与我的问题有关?



EDIT 21/9/2015:



我的应用程序在这个周末下降了。这是从昨天的错误日志(当我相信它下降)的堆栈跟踪:

  2015年9月20日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上下文与路径[/ Harmonizome] threw异常
org.hibernate.exception.GenericJDBCException:无法打开连接
在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)
在org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:224)
在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)
在com.google.gson.TreeTypeAdapter.write(TreeTypeAdapter.java:70)
在com.google .gson.Gson.toJson(Gson.java:600)
在com.google.gson.Gson.toJson(Gson.java:579)
在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)
在org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
在org.apache。 catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
在org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
在org.apache.catalina.authenticator。 AuthenticatorBase.invoke(AuthenticatorBase.java:502)
在org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
在org.apache.catalina.valves.ErrorReportValve.invoke ErrorReportValve.java:79)
在org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
在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)
在java.util.concurrent.ThreadPoolExecutor $ Worker.run(ThreadPoolExecutor.java:617)
在org.apache .tomcat.util.threads.TaskThread $ WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
引发者:org.apache.tomcat .jdbc.pool.PoolExhaustedException:[http-apr-8080-exec-35]超时:池空。无法在30秒内获取连接,无法使用[size:5;忙:5; idle:0; lastwait:30000]。
在org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
在org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:672)
at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
at org.hibernate.connection.TomcatJDBCConnectionProvider.getConnection(TomcatJDBCConnectionProvider.java:208)
在org.hibernate.internal.AbstractSessionImpl $ NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292)
在org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297)



这是我从MySQL的连接变量:

  mysql> SHOW VARIABLES LIKE'%connect%'; 
+ --------------------------------------------- - + ----------------- +
| Variable_name |价值|
+ --------------------------------------------- - + ----------------- +
| character_set_connection | utf8 |
| collat​​ion_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 |价值|
+ ----------------------------- + ---------- +
| 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 |
+ ----------------------------- + ---------- +

EDIT 22/9/2015:



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]在上下文中与路径[ / Harmonizome] threw exception [javax.servlet.ServletException:javax.servlet.jsp.JspException:In& lt; parseDate& gt,parse locale不能建立]与根本原因
javax.servlet.jsp .JspException:在& lt; parseDate& gt中,无法在org.apache.taglibs.standard.tag.common.fmt.ParseDateSupport.doEndTag(ParseDateSupport.java:147)上创建一个解析语言环境

附加JConsole堆内存使用输出:





JConsole输出为线程使用;它开始在24-25左右,跳跃到34,一旦我开始使用该网站。即使在关闭浏览器窗口后,仍保留在那里:





EDIT 23/9/2015:



我在问题开始之前更改了一件事是如何处理Hibernate交易。以前,我有 enable_lazy_load_no_trans disabled(这是默认值)。以前,我使用的是开放会议视图模式。看起来人们不喜欢打开会话的视图模式,所以我启用了 enable_lazy_load_no_trans 。因此,我有这样的代码:

  List< MyObjects> myObjects = null; 
try {
HibernateUtil.beginTransaction();
myObjects = //从DB获取我的对象
HibernateUtil.commitTransaction();
} catch(HibernateException he){
HibernateUtil.rollbackTransaction();
} finally {
HibernateUtil.close();
}

//在JSP / JSTL中渲染myObjects
//此JSP可能会延迟加载相关对象

回想起来,这似乎...有问题。我不知道Hibernate何时释放对象。

解决方案

从提供的堆栈跟踪,



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



我建议您开始使用 FlexyPool ,它支持Tomcat DBCP,并更好地了解连接和事务使用情况。
本文说明您可能使用的直方图感兴趣的,如连接获取时间和连接租用时间。



为了安全,检查MySQL驱动程序版本,看看你是否在运行过时的图书馆。


For months, my web application ran smoothly, but for the past week or two, it keeps dropping its connection to MySQL server. I'm not a DBA guy and have no idea how to debug this.

Here is what I know:

  1. The connection seems to drop every few hours. Sometimes during the day, but always during the night.
  2. My lab has a MySQL server that hosts databases for multiple applications.
  3. Currently, we have 46 connections to the MySQL server.
  4. To my knowledge, no other application is experiencing this issue.
  5. My application is using the same stack, configuration, and even code for connecting to the DB as another application—this other application supports around 200 users per day and has been running smoothly since 2013.
  6. Both applications use Hibernate ORM; this is the only configuration that I know of:

    <!-- 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>
    

  7. The issue started around the same time as when someone tried to use the application's RESTful API to download our data. This user—actually a collaborator—has a small script iterates over every row in a specific table and requests all the metadata.

  8. The issue also started around the same time that my lab started offering a Coursera Massive Open Online Course. I don't know what the numbers are, but the actual usage on the site must have jumped.

I'm aware that this is a broad question, but I'm really at a loss as to how to go about debugging this. Any suggestions are appreciated.

EDIT:

Digging around the other application's ServletContextListener, I found this bit of code that my contextDestroyed function does not have:

// 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
        }
    }
}

It appears to iterate over the stack traces, find the one with the text "Abandoned connection cleanup thread" and manually stop it. It seems probably that this is related to my issue?

EDIT 21/9/2015:

My application went down this weekend. Here is the stack trace from the error log from yesterday (when I believe it went down):

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)

Here is are my connection variables from 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    |
+-----------------------------+----------+

EDIT 22/9/2015:

Would a SEVERE Tomcat error cause the issue? I am seeing an error, unrelated to the database, about parsing a date:

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)

Attaching JConsole output of heap memory usage:

JConsole output for thread usage; it started around 24-25 and jumped up to 34 once I started using the site. Even after closing the browser window, it remained there:

EDIT 23/9/2015:

One thing I changed right before the issue began was how I deal with Hibernate transactions. Previously, I had enable_lazy_load_no_trans disabled (which is the default). Previously, I was using the "open session in view" pattern. It seemed like people didn't like the open session in view pattern, so I enabled enable_lazy_load_no_trans. Thus, I have code like this:

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

In retrospect, this seems... problematic. I have no idea when Hibernate "lets go" of the objects.

解决方案

From the stack-trace you provided, I can draw a single conclusion: you are simply running out of connections.

This can be caused by long running transactions, possibly due to slow queries or improper application transaction boundaries.

I suggest you start using FlexyPool, which supports Tomcat DBCP, and get a better understanding of both the connection and the transaction usage. This article explains the histograms you might be interested in, like connection acquire time and connection lease time.

Just to be on the safe side, check the MySQL driver version too and see if you're running on an outdated library.

这篇关于MySQL / Hibernate - 如何调试一个MySQL池连接不断丢弃?的文章就介绍到这了,希望我们推荐的答案对大家有所帮助,也希望大家多多支持IT屋!

查看全文
登录 关闭
扫码关注1秒登录
发送“验证码”获取 | 15天全站免登陆