MySQL error during large queries. Timeout related?

[WRP]

We receive the following error in QM when generating a large custom report:

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]

We would appreciate any support that you can provide!

[QueueMetrics]

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]

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]

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]

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:

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:

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]

How much memory does QM have? how many result rows is this query?

[WRP]

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]

I was thinking that this would lessen garbage collections and thence make reading quicker.
There must be a timeout somewhere?

[WRP]

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]

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.