Per mesi, la mia applicazione web ha funzionato senza intoppi, ma negli ultimi due giorni, continua a lasciare la sua connessione al server MySQL. Non sono un ragazzo DBA e non ho idea di come eseguire il debug di questo.MySQL/Hibernate - Come si esegue il debug di una connessione in pool MySQL che continua a cadere?
Ecco quello che so:
- Il collegamento sembra far cadere ogni poche ore. A volte durante il giorno, ma sempre durante la notte.
- Il mio laboratorio ha un server MySQL che ospita database per più applicazioni.
- Attualmente, abbiamo 46 connessioni al server MySQL.
- A mia conoscenza, nessun'altra applicazione sta riscontrando questo problema.
- La mia applicazione utilizza lo stesso stack, la configurazione, e anche il codice per la connessione al DB come un'altra applicazione-quest'altra applicazione supporta circa 200 utenti al giorno ed è stato in esecuzione senza problemi dal 2013.
Entrambe le applicazioni utilizzano Hibernate ORM; questa è l'unica configurazione che io conosca:
<!-- 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>La questione ha iniziato intorno allo stesso tempo come quando qualcuno ha cercato di utilizzare API RESTful dell'applicazione per scaricare i nostri dati. Questo utente, in realtà un collaboratore, ha un piccolo script che scorre su ogni riga in una tabella specifica e richiede tutti i metadati.
- Il problema è iniziato anche nello stesso periodo in cui il mio laboratorio ha iniziato a offrire un corso online aperto Coursera Massive. Non so quali siano i numeri, ma l'utilizzo effettivo sul sito deve essere saltato.
Sono consapevole che questa è una domanda ampia, ma sono davvero in perdita su come eseguire il debug di questo. Qualsiasi suggerimento è apprezzato.
EDIT:
Scavando attorno l'altra applicazione del ServletContextListener, ho trovato questo pezzo di codice che la mia funzione contextDestroyed non ha:
// 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
}
}
}
Sembra per scorrere i tracce dello stack, trovo quello con il testo "Abandoned connection cleanup thread" e fermarlo manualmente. Sembra probabilmente che questo è legato al mio problema?
EDIT 21/9/2015:
La mia domanda è andato giù questo fine settimana. Ecco l'analisi dello stack dal log degli errori di ieri (quando credo è andato giù):
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)
Ecco le mie variabili di connessione da 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 :
Un errore di Tomcat causerebbe il problema? SEVERE?Sto vedendo un errore, non correlato alla banca dati, circa l'analisi di un Data:
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 <parseDate>, a parse locale can not be established] with root cause
javax.servlet.jsp.JspException: In <parseDate>, a parse locale can not be established
at org.apache.taglibs.standard.tag.common.fmt.ParseDateSupport.doEndTag(ParseDateSupport.java:147)
Collegamento uscita JConsole di utilizzo della memoria heap:
uscita JConsole per l'utilizzo di thread; è iniziato intorno al 24-25 e saltato fino a 34 una volta che ho iniziato a utilizzare il sito. Anche dopo la chiusura della finestra del browser, è rimasto lì:
EDIT 23/9/2015:
Una cosa che ho cambiato a destra prima del problema ha iniziato era come mi occupo di transazioni Hibernate. In precedenza, avevo enable_lazy_load_no_trans disabilitato (che è l'impostazione predefinita). In precedenza, stavo usando il modello "open session in view". Sembrava che alla gente non piacesse la sessione aperta in modalità visualizzazione, quindi ho abilitato lo enable_lazy_load_no_trans. Quindi, ho un codice come questo:
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 retrospettiva, questo sembra ... problematico. Non ho idea di quando Hibernate "lascia andare" gli oggetti.
Problema di memoria? Qualsiasi altra applicazione è stata distribuita sulla macchina su cui sono stati distribuiti Mysql e Application? – Gaurav
Non ho esperienza con questa implementazione del pool di connessioni, ma inizierei a eseguire il debug con l'implementazione di QueryTimeoutInterceptor: https://tomcat.apache.org/tomcat-7.0-doc/jdbc-pool.html#org.apache.tomcat. jdbc.pool.interceptor.QueryTimeoutInterceptor – a1ex07
@Gaurav, un paio di altre piccole applicazioni sono in esecuzione sulla stessa macchina. Abbiamo un cluster e, per motivi storici, ho avuto un vincolo per eseguire l'applicazione sulla stessa macchina ogni volta, ma sono stato ridistribuito in modo che possa essere eseguito ovunque, nel caso in cui una macchina abbia problemi. – gwg