SQL Server Read Time Out Issues - invokeAsync

Ignition
, , ,
1

Having issues with a named query read timeout. The query takes about 3 seconds to execute from SSMS.

Full Trace:

Error running function from system.util.invokeAsynchronous
com.inductiveautomation.ignition.common.script.JythonExecException: Traceback (most recent call last): File "", line 17, in logTagChange at com.inductiveautomation.ignition.gateway.db.namedquery.NamedQueryExecutor$NamedQueryInstance.execute(NamedQueryExecutor.java:407) at com.inductiveautomation.ignition.gateway.db.namedquery.NamedQueryExecutor.execute(NamedQueryExecutor.java:173) at com.inductiveautomation.ignition.gateway.db.namedquery.GatewayNamedQueryManager.execute(GatewayNamedQueryManager.java:92) at com.inductiveautomation.ignition.gateway.script.GatewayDBUtilities.runNamedQuery(GatewayDBUtilities.java:418) at jdk.internal.reflect.GeneratedMethodAccessor36.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.base/java.lang.reflect.Method.invoke(Unknown Source) java.lang.Exception: java.lang.Exception: com.microsoft.sqlserver.jdbc.SQLServerException: Read timed out

at org.python.core.Py.JavaError(Py.java:547)

at org.python.core.Py.JavaError(Py.java:538)

at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:192)

at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:541)

at org.python.core.PyObject.__call__(PyObject.java:494)

at org.python.core.PyObject.__call__(PyObject.java:498)

at org.python.pycode._pyx154.logTagChange$1(:17)

at org.python.pycode._pyx154.call_function()

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:306)

at org.python.core.PyFunction.function___call__(PyFunction.java:474)

at org.python.core.PyFunction.__call__(PyFunction.java:469)

at org.python.core.PyFunction.__call__(PyFunction.java:464)

at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:831)

at com.inductiveautomation.ignition.gateway.script.GatewaySystemUtilities.lambda$_invokeAsyncImpl$0(GatewaySystemUtilities.java:142)

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

Caused by: org.python.core.PyException: java.lang.Exception: java.lang.Exception: com.microsoft.sqlserver.jdbc.SQLServerException: Read timed out

... 16 common frames omitted

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

at com.inductiveautomation.ignition.gateway.db.namedquery.NamedQueryExecutor$NamedQueryInstance.execute(NamedQueryExecutor.java:407)

at com.inductiveautomation.ignition.gateway.db.namedquery.NamedQueryExecutor.execute(NamedQueryExecutor.java:173)

at com.inductiveautomation.ignition.gateway.db.namedquery.GatewayNamedQueryManager.execute(GatewayNamedQueryManager.java:92)

at com.inductiveautomation.ignition.gateway.script.GatewayDBUtilities.runNamedQuery(GatewayDBUtilities.java:418)

at jdk.internal.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)

at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.base/java.lang.reflect.Method.invoke(Unknown Source)

at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190)

... 13 common frames omitted

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

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

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

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

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

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

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

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

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

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

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

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

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:306)

at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)

at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)

at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper$SRPreparedStatement.executeUpdate(SRConnectionWrapper.java:981)

at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper.runPrepUpdate(SRConnectionWrapper.java:181)

at com.inductiveautomation.ignition.gateway.db.namedquery.NamedQueryExecutor$NamedQueryInstance.runPrepQuery(NamedQueryExecutor.java:507)

at com.inductiveautomation.ignition.gateway.db.namedquery.NamedQueryExecutor$NamedQueryInstance.execute(NamedQueryExecutor.java:399)

... 20 common frames omitted

I have the DB configured for up to 550 connections, but never see it over 390.

2

I’ve found that this is actually an issue with the invokeAsynchronous call.

I have this same query called from tagChange scripts and from a timed script. The timed script is for tags that don’t change all that much, but are needed for trending, so I force it to update the DB every 10 seconds. If I comment out the invokeAsync calls all of the tagChange calls work just fine. If I don’t use async the timed script takes over 3.5 minutes (~5 seconds for each of the 44 tags).

3

So I guess the problem is I’m trying to run a 3.5 minute script every 10 seconds. That’s never going to work.

4

What are you doing that takes 5 seconds per tag? I struggle to think of anything that should take that long.

1 Like
5

What are you doing that takes 5 seconds per tag? I struggle to think of anything that should take that long.

The DB read query takes 3 seconds.

SELECT TOP 1 val, t_stamp FROM Data where tag_id=:tag_name order by t_stamp desc
6

This is unsolicited advice, so feel free to disregard it if you would like to:

For my applications, I would describe a 3-second query that returns 1 row as unacceptably long. Consider indexing your table or upsizing your database hardware to achieve better performance. If you’re interested in doing this, some questions to start with are:

  • What brand of database are you using (Looks like MS SQL Server based on TOP 1)?
  • How many rows are in this table?
  • Does the table have a declared primary key?
  • Does the table have any indexing on it currently?
1 Like
7

I agree it seems long. I don’t think the query takes that long in reality.

I am using SQL Express.

Now that I’ve gotten rid of the async calls everything is running MUCH smoother.

Before removing async calls

My DB connections were up in the 380's
My DB throughput was ~4.3 queries/sec
SSMS was very slow to respond
Executing my named query directly in SSMS took 3 seconds

After removing async calls

My DB connections are 0
My DB throughput is 27.9+ queries/sec
SSMS is much more responsive
Executing my named query directly in SSMS took almost no time

I also noticed, before I got rid of the async calls, if disabled the DB connection to Ignition and ran my query on static tables, it took almost no time at all (the counter at the bottom of SSMS says 00:00:00). Then, after re-enabling it took 3 seconds.

To your other concerns, yes there’s a primary key and I’ve indexed the tag name and date.

1 Like