Author Topic: MySQL error during large queries. Timeout related?  (Read 10962 times)

WRP

  • Jr. Member
  • **
  • Posts: 57
  • Karma: 1
    • View Profile
MySQL error during large queries. Timeout related?
« on: December 17, 2012, 20:23:05 »
We receive the following error in QM when generating a large custom report:

Quote
Error (tech) in class 'it.loway.app.queuemetrics.caricamento.caricaCoda'. -- Inner Exception -- - Exception: it.loway.tpf.common.exceptions.TechException - - Stack trace: - Problem on DB: Database error: - -- Inner Exception -- - Exception: com.mysql.jdbc.CommunicationsException - Error: - Communications link failure due to underlying exception: - - ** BEGIN NESTED EXCEPTION ** - - java.io.EOFException - MESSAGE: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost. - - STACKTRACE: - - 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:1997) - at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2411) - at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916) - at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631) - at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723) - at com.mysql.jdbc.Connection.execSQL(Connection.java:3277) - at com.mysql.jdbc.Connection.execSQL(Connection.java:3206) - at com.mysql.jdbc.Statement.executeQuery(Statement.java:1232) - at it.loway.tpf.SQL.selectScalare(SQL.java:318) - at it.loway.app.queuemetrics.caricamento.caricaCoda.runDataAnalysis(caricaCoda.java:408) - at it.loway.app.queuemetrics.caricamento.caricaCoda.doRun(caricaCoda.java:83) - at it.loway.tpf.transaction.servlets.LowayTransactionController.runVerb(LowayTransactionController.java:276) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequest(LowayTransactionController.java:566) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequestWrapper(LowayTransactionController.java:387) - at it.loway.tpf.transaction.servlets.LowayTransactionController.doPost(LowayTransactionController.java:238) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) - at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) - at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) - at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) - at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) - at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) - at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) - at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) - at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:291) - at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859) - at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602) - at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) - at java.lang.Thread.run(Thread.java:662) - - - ** END NESTED EXCEPTION ** - - - - Last packet sent to the server was 3 ms ago. - Stack trace: - com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception: - - ** BEGIN NESTED EXCEPTION ** - - java.io.EOFException - MESSAGE: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost. - - STACKTRACE: - - 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:1997) - at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2411) - at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916) - at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631) - at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723) - at com.mysql.jdbc.Connection.execSQL(Connection.java:3277) - at com.mysql.jdbc.Connection.execSQL(Connection.java:3206) - at com.mysql.jdbc.Statement.executeQuery(Statement.java:1232) - at it.loway.tpf.SQL.selectScalare(SQL.java:318) - at it.loway.app.queuemetrics.caricamento.caricaCoda.runDataAnalysis(caricaCoda.java:408) - at it.loway.app.queuemetrics.caricamento.caricaCoda.doRun(caricaCoda.java:83) - at it.loway.tpf.transaction.servlets.LowayTransactionController.runVerb(LowayTransactionController.java:276) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequest(LowayTransactionController.java:566) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequestWrapper(LowayTransactionController.java:387) - at it.loway.tpf.transaction.servlets.LowayTransactionController.doPost(LowayTransactionController.java:238) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) - at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) - at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) - at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) - at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) - at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) - at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) - at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) - at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:291) - at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859) - at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602) - at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) - at java.lang.Thread.run(Thread.java:662) - - - ** END NESTED EXCEPTION ** - - - - Last packet sent to the server was 3 ms ago. - at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2622) - at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916) - at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631) - at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723) - at com.mysql.jdbc.Connection.execSQL(Connection.java:3277) - at com.mysql.jdbc.Connection.execSQL(Connection.java:3206) - at com.mysql.jdbc.Statement.executeQuery(Statement.java:1232) - at it.loway.tpf.SQL.selectScalare(SQL.java:318) - at it.loway.app.queuemetrics.caricamento.caricaCoda.runDataAnalysis(caricaCoda.java:408) - at it.loway.app.queuemetrics.caricamento.caricaCoda.doRun(caricaCoda.java:83) - at it.loway.tpf.transaction.servlets.LowayTransactionController.runVerb(LowayTransactionController.java:276) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequest(LowayTransactionController.java:566) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequestWrapper(LowayTransactionController.java:387) - at it.loway.tpf.transaction.servlets.LowayTransactionController.doPost(LowayTransactionController.java:238) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) - at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) - at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) - at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) - at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) - at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) - at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) - at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) - at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:291) - at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859) - at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602) - at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) - at java.lang.Thread.run(Thread.java:662) - -- End Inner Exception -- - - When running: SELECT announcement_duration FROM code_possibili WHERE id_coda = '40' - at it.loway.tpf.SQL.selectScalare(SQL.java:327) - at it.loway.app.queuemetrics.caricamento.caricaCoda.runDataAnalysis(caricaCoda.java:408) - at it.loway.app.queuemetrics.caricamento.caricaCoda.doRun(caricaCoda.java:83) - at it.loway.tpf.transaction.servlets.LowayTransactionController.runVerb(LowayTransactionController.java:276) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequest(LowayTransactionController.java:566) - at it.loway.tpf.transaction.servlets.LowayTransactionController.serveRequestWrapper(LowayTransactionController.java:387) - at it.loway.tpf.transaction.servlets.LowayTransactionController.doPost(LowayTransactionController.java:238) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) - at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) - at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) - at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) - at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) - at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) - at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) - at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) - at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) - at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:291) - at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859) - at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602) - at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) - at java.lang.Thread.run(Thread.java:662) - -- End Inner Exception -- -

We have tried adding "socketTimeout=0" to the JDBC_URL setting in WEB-INF/web.xml, but this hasn't helped.

WRP

  • Jr. Member
  • **
  • Posts: 57
  • Karma: 1
    • View Profile
Re: MySQL error during large queries. Timeout related?
« Reply #1 on: December 20, 2012, 01:13:37 »
We would appreciate any support that you can provide!

QueueMetrics

  • Loway
  • Hero Member
  • *
  • Posts: 2993
  • Karma: 39
    • View Profile
    • QueueMetrics
Re: MySQL error during large queries. Timeout related?
« Reply #2 on: December 21, 2012, 11:07:24 »
The error you are having looks like an awful "slow query" where MySQL does not even start sending data before the timeout. You may want to avoid this by setting "enableQueryTimeouts=false" but this is frankly the first time I hear of such an issue.

Makes me think that e.g. your MySQL table has corrupted indexes, as all Qm activity is indexed so it should never have a huge timeout while MySQL is "thinking".

WRP

  • Jr. Member
  • **
  • Posts: 57
  • Karma: 1
    • View Profile
Re: MySQL error during large queries. Timeout related?
« Reply #3 on: December 27, 2012, 22:18:54 »
How would we go about fixing these corrupted indexes in the case of the QM database?

As I recall, we ran into a slow query issue a number of years ago. The solution, which you provided, ultimately had to do with optimizing the tables every week or so.

QueueMetrics

  • Loway
  • Hero Member
  • *
  • Posts: 2993
  • Karma: 39
    • View Profile
    • QueueMetrics
Re: MySQL error during large queries. Timeout related?
« Reply #4 on: December 31, 2012, 12:39:20 »
You just drop the indexes and re-create them. MySQL sometimes notices a corrupted index and silently tries working around the problem by reading all data in a table scan.... but performance gets awful.

WRP

  • Jr. Member
  • **
  • Posts: 57
  • Karma: 1
    • View Profile
Re: MySQL error during large queries. Timeout related?
« Reply #5 on: January 08, 2013, 19:57:59 »
I tried your two recommendations but they unfortunately didn't work. I:

1. recreated the indexes for the tables being queried
2. added 'enableQueryTimeout=true' to the JDBC_URL setting in web.xml

I enabled slow query logging with MySQL and found this to be (at least one of) the slow queries:

Quote
SELECT `time_id` , `call_id` , `queue` , `agent` , `verb` , `data1` , `data2` , `data3` , `data4` , `data5` , `unique_row_count`   FROM queue_log  WHERE  `partition` ='P001' AND        (`time_id` >= '1325433600' AND `time_id`<= '1357672768' )  AND `queue` IN ( '', 'NONE'  , 'q-301'  , '3000'  , '3012'  , '3011'  , '3010'  , 'none'  , '3003'  , '3200'  , '3009'  , 'q-300'  , '3008' )   ORDER BY `time_id` ASC , `unique_row_count` ASC;


If I run this command from the MySQL CLI client, it completes after about 25-30 seconds. When I run the custom report, it dies consistently after about 37 seconds.

In case it is of any use, here is our JDBC_URL value:
Quote
jdbc:mysql://localhost/queuemetrics?sessionVariables=sql_mode=''&amp;autoReconnect=true&amp;zeroDateTimeBehavior=convertToNull&amp;jdbcCompliantTruncation=false&amp;user=queuemetrics&amp;password=[removed]&amp;socketTimeout=0&amp;enableQueryTimeouts=false

What else can we try to remedy this issue? Thanks.



QueueMetrics

  • Loway
  • Hero Member
  • *
  • Posts: 2993
  • Karma: 39
    • View Profile
    • QueueMetrics
Re: MySQL error during large queries. Timeout related?
« Reply #6 on: January 15, 2013, 12:30:09 »
How much memory does QM have? how many result rows is this query?

WRP

  • Jr. Member
  • **
  • Posts: 57
  • Karma: 1
    • View Profile
Re: MySQL error during large queries. Timeout related?
« Reply #7 on: January 15, 2013, 18:09:32 »
The result returns just short of 1.2 million results. We have 3072 MB of memory allocated to QM (-Xms3072M -Xmx3072M).

I increased both of the memory settings to 5120M and restarted queuemetrics but saw the same error message when generating the custom report.

QueueMetrics

  • Loway
  • Hero Member
  • *
  • Posts: 2993
  • Karma: 39
    • View Profile
    • QueueMetrics
Re: MySQL error during large queries. Timeout related?
« Reply #8 on: January 16, 2013, 12:22:55 »
I was thinking that this would lessen garbage collections and thence make reading quicker.
There must be a timeout somewhere?

WRP

  • Jr. Member
  • **
  • Posts: 57
  • Karma: 1
    • View Profile
Re: MySQL error during large queries. Timeout related?
« Reply #9 on: January 16, 2013, 18:31:17 »
We have not (that I'm aware of) added any timeout logic. And again, the query works from the MySQL CLI client. Would it help if we sent you our config files directly?

QueueMetrics

  • Loway
  • Hero Member
  • *
  • Posts: 2993
  • Karma: 39
    • View Profile
    • QueueMetrics
Re: MySQL error during large queries. Timeout related?
« Reply #10 on: January 21, 2013, 10:01:28 »
One thing you could do is to try changing the connector/j QM uses to a version pre 5.xx as this should not support the query timeout.