Easy Chart Real/Historical Query timeout error

robertm · December 11, 2020, 7:31pm

I’m trying to add a single tag to an new Easy Chart…existing Historical DB that’s logging other tags. The tag in question is a UDT that was drag/drop from CLX. The member I’m after is Level_Percent, a float. I’ve edited that member of the UDT, enabled Historical, selected the existing SQL DB for provider, set polling to 2 sec. Refresh tag and it shows up in the Easy Chart pick list. Whether I pick the tag, or drag it from the tag browser into the Chart, and whether I enable Realtime or Historical, the Chart immediately gives a Query timeout error. What step am I missing?

java.lang.Exception: Error running query:

TagHistory(paths=[prov:default:/tag:Crushing_PLC/Cru_Finish_Tank1/Level_Percent], start=Fri Dec 11 13:53:00 EST 2020, end=Fri Dec 11 14:03:59 EST 2020, flags=0)@0ms

On: Historical_Data (2).Root Container.Easy Chart

at com.inductiveautomation.factorypmi.application.gateway.QueryManager$QueryExecutor.run(QueryManager.java:309)

at java.base/java.lang.Thread.run(Unknown Source)

Caused by: com.inductiveautomation.ignition.client.gateway_interface.GatewayException: Read timed out

at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.newGatewayException(GatewayInterface.java:351)

at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:325)

at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.runTagHistoryQuery(GatewayInterface.java:769)

at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.runTagHistoryQuery(GatewayInterface.java:737)

at com.inductiveautomation.factorypmi.application.gateway.GwiTagHistoryProvider.query(GwiTagHistoryProvider.java:16)

at com.inductiveautomation.ignition.common.sqltags.history.cache.TagHistoryCache.query(TagHistoryCache.java:211)

at com.inductiveautomation.factorypmi.application.gateway.TagHistoryQuery.execute(TagHistoryQuery.java:34)

at com.inductiveautomation.factorypmi.application.gateway.QueryManager$Query.execute(QueryManager.java:657)

at com.inductiveautomation.factorypmi.application.gateway.QueryManager$QueryExecutor.run(QueryManager.java:306)

... 1 more

Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Read timed out

at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:2826)

at com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:1977)

at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(IOBuffer.java:6369)

at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:7627)

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:576)

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:508)

at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7240)

at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:2869)

at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:243)

at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:218)

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeQuery(SQLServerPreparedStatement.java:434)

at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:122)

at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:122)

at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper$SRPreparedStatement.executeQuery(SRConnectionWrapper.java:1008)

at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper.runPrepQuery(SRConnectionWrapper.java:169)

at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper.runPrepLimitQuery(SRConnectionWrapper.java:214)

at com.inductiveautomation.gateway.tags.history.query.DatasourceQueryExecutor.runSpecialValueQuery(DatasourceQueryExecutor.java:917)

at com.inductiveautomation.gateway.tags.history.query.DatasourceQueryExecutor.readCompletionValues(DatasourceQueryExecutor.java:790)

at com.inductiveautomation.gateway.tags.history.query.DatasourceQueryExecutor.primeRead(DatasourceQueryExecutor.java:957)

at com.inductiveautomation.ignition.gateway.sqltags.history.query.AbstractHistoryLoader.startReading(AbstractHistoryLoader.java:104)

at com.inductiveautomation.ignition.gateway.sqltags.history.query.AggregateHistoryQueryExecutor.startReading(AggregateHistoryQueryExecutor.java:85)

at com.inductiveautomation.ignition.gateway.sqltags.history.query.HistoryWriter.readData(HistoryWriter.java:312)

at com.inductiveautomation.ignition.gateway.sqltags.history.query.HistoryWriter.execute(HistoryWriter.java:230)

at com.inductiveautomation.ignition.gateway.sqltags.history.TagHistoryManagerImpl.queryHistory(TagHistoryManagerImpl.java:511)

at com.inductiveautomation.ignition.gateway.tags.model.ProjectDefaultTagManagerFacade.queryHistory(ProjectDefaultTagManagerFacade.java:424)

at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.QueryTagHistory.invoke(QueryTagHistory.java:90)

at com.inductiveautomation.ignition.gateway.servlets.Gateway.doPost(Gateway.java:414)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

at com.inductiveautomation.ignition.gateway.bootstrap.MapServlet.service(MapServlet.java:86)

at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322)

at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)

at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

at org.eclipse.jetty.server.Server.handle(Server.java:500)

at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)

at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)

at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)

at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)

at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)

at java.lang.Thread.run(null)

Ignition v8.0.15 (b2020072213)

Java: Azul Systems, Inc. 11.0.6

robertm · December 12, 2020, 2:41pm

quarantine.zip (217.8 KB) quarantine.zip (217.8 KB) Upon further investigation, there seems to be an issue with the DataCollection DB. On the gateway, it shows active, connected, etc, but it shows 16K quarantined items. This is not my installation, but one I’m coming into late in the game and assisting with. I’ve attached the quarantined XML file…Can anyone point me as to what to look at or what might be going on?

pturmel · December 12, 2020, 5:33pm

Without personally looking at your DB, I can’t say with any certainty, but your symptoms suggest broken/missing indices.

{ Consider editing your post, selecting the error text, and clicking the pre-format button </> so that it is readable. Also, consider excerpting a few sample entries from your quarantine file and posting directly, with the pre-formatting applied. Most volunteers here are not enthusiastic about downloading and searching through large zip files. }

robertm · December 14, 2020, 2:21pm

<?xml version="1.0"?>

-<cachedata creationTime="Sat Dec 12 09:32:55 EST 2020" sourceStore="DataCollection">


-<data subtype="" flavor="__sqltaghistory__">


-<scanclassset provider="default" gateway="Ignition-INDSV139TS" exectime="Tue Dec 01 03:20:16 EST 2020" rate="-1" name="_exempt_">

<value quality="192" timestamp="2020-12-01 03:20:14.760" timesource="1" mode="0" datatype="0" path="DataFromMain_int7/DataFromMain_int7_23_">147</value>

<value quality="192" timestamp="2020-12-01 03:20:14.760" timesource="1" mode="0" datatype="0" path="DataFromMain_int7/FPL Exit temp">921</value>

</scanclassset>


-<scanclassset provider="default" gateway="Ignition-INDSV139TS" exectime="Tue Dec 01 03:20:16 EST 2020" rate="3000" name="Default">

<value quality="192" timestamp="2020-12-01 03:20:14.813" timesource="0" mode="0" datatype="0" path="DataForEPASystems/RTOTemp_B_Avg">146,018</value>

<value quality="192" timestamp="2020-12-01 03:20:14.813" timesource="0" mode="0" datatype="0" path="DataFromMain_Int18/ProcessWaterPSI">-906</value>

</scanclassset>


-<scanclassset provider="default" gateway="Ignition-INDSV139TS" exectime="Tue Dec 01 03:20:21 EST 2020" rate="-1" name="_exempt_">

<value quality="192" timestamp="2020-12-01 03:20:19.401" timesource="1" mode="0" datatype="0" path="DataFromMain_Int3/Booleans_S2_144">-32,443</value>

<value quality="192" timestamp="2020-12-01 03:20:07.655" timesource="1" mode="3" datatype="1" path="Dedicated Hot Oil Filler Heater/AI_PT1419/Data">85.3563232421875</value>

<value quality="192" timestamp="2020-12-01 03:20:19.401" timesource="1" mode="0" datatype="0" path="DataFromMain_Int3/CopperMachineBin">0</value>

</scanclassset>


-<scanclassset provider="default" gateway="Ignition-INDSV139TS" exectime="Tue Dec 01 03:20:19 EST 2020" rate="-1" name="_exempt_">

<value quality="192" timestamp="2020-12-01 03:20:19.425" timesource="1" mode="0" datatype="0" path="DataFromMain_int1_Silos/DataFromMain_int1_36_">1,860</value>

<value quality="192" timestamp="2020-12-01 03:20:19.425" timesource="1" mode="0" datatype="0" path="DataFromMain_int1_Silos/DataFromMain_int1_29_">1,416</value>

<value quality="192" timestamp="2020-12-01 03:20:19.425" timesource="1" mode="0" datatype="0" path="DataFromMain_int2/Hot oil heater">5,579</value>

<value quality="192" timestamp="2020-12-01 03:20:19.425" timesource="1" mode="0" datatype="0" path="DataFromMain_int1_Silos/DataFromMain_int1_13_">908</value>

<value quality="192" timestamp="2020-12-01 03:20:19.425" timesource="1" mode="0" datatype="0" path="DataFromMain_int1_Silos/DataFromMain_int1_49_">-3,459</value>

</scanclassset>

pturmel · December 14, 2020, 2:28pm

Yeah, almost certainly broken indices making it impossible to query or insert history within the normal (60 second) timeout.

Indices on timestamp and tag id are necessary. What DB type? Is it in the same server as Ignition? Or separate? (Hopefully the latter.) What indices are present on the history tables?

robertm · December 14, 2020, 9:34pm

It would appear the same server…It’s location is localhost. One thing I did notice poking around, is that in the extra connections dialog, it says DatabaseName = DataCollection1 instead of matching the actual Database name of DataCollection. There are two other working DB’s (Alarm and the default historical data), and their property DatabaseName matches exactly. Could this be someone’s typo causing issues? Is that normally filled in by default when the DB is created? Because someone has modified it adding additional properties for timeout values, extending them.

pturmel · December 14, 2020, 10:08pm

Having the wrong database name would be a big problem. It is not filled in automatically, so a typo is likely. Being on the same machine is a long-term problem, usually.