[BUG] java.util.concurrent.TimeoutException running system.tag.readBlocking

v8.3.3

I’m trying to read 92,907 tagpaths with system.tag.readBlocking (i’ve read tonnes more than this in earlier versions ok) from the script console through a standard tag provider, but i’m getting this exception after the default timeout period, 45s:

Java Traceback:
Traceback (most recent call last):
  File "<input>", line 66, in <module>
	at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source)

	at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source)

	at com.inductiveautomation.ignition.client.script.ClientTagUtilities.readBlockingImpl(ClientTagUtilities.java:204)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractTagUtilities.readBlocking(AbstractTagUtilities.java:565)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

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

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

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

java.util.concurrent.TimeoutException: java.util.concurrent.TimeoutException


	at org.python.core.PyException.doRaise(PyException.java:211)

	at org.python.core.Py.makeException(Py.java:1654)

	at org.python.core.Py.makeException(Py.java:1658)

	at org.python.core.Py.makeException(Py.java:1662)

	at org.python.core.Py.makeException(Py.java:1666)

	at org.python.pycode._pyx43.f$0(<input>:83)

	at org.python.pycode._pyx43.call_function(<input>)

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

	at org.python.core.PyCode.call(PyCode.java:18)

	at org.python.core.Py.runCode(Py.java:1703)

	at org.python.core.Py.exec(Py.java:1747)

	at org.python.util.PythonInterpreter.exec(PythonInterpreter.java:277)

	at org.python.util.InteractiveInterpreter.runcode(InteractiveInterpreter.java:130)

	at com.inductiveautomation.ignition.designer.gui.tools.jythonconsole.JythonConsole$ConsoleWorker.doInBackground(JythonConsole.java:639)

	at com.inductiveautomation.ignition.designer.gui.tools.jythonconsole.JythonConsole$ConsoleWorker.doInBackground(JythonConsole.java:627)

	at java.desktop/javax.swing.SwingWorker$1.call(Unknown Source)

	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)

	at java.desktop/javax.swing.SwingWorker.run(Unknown Source)

	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

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

Traceback (most recent call last):
  File "<input>", line 66, in <module>
	at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source)

	at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source)

	at com.inductiveautomation.ignition.client.script.ClientTagUtilities.readBlockingImpl(ClientTagUtilities.java:204)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractTagUtilities.readBlocking(AbstractTagUtilities.java:565)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

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

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

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

java.util.concurrent.TimeoutException: java.util.concurrent.TimeoutException

I’ve increased timeout to 10mins and same thing…

I can’t even read 20,000 tagpaths within 120s without it producing that error…

There seem to be some major bugs within 8.3 relating to reading tags via script

Creating a gateway message handler that calls the tag.readBlocking function and returning the result, and calling that with system.util.sendRequest gets around the issue, but obviously more annoying to use

Can you test if this is still an issue in 8.3.5? Can you post the script you are using? What is the persistence setting being used for your tags? What is the breakdown of tag types?

I tested locally on my laptop, and was able to read 153000 tags in under 6 seconds.

1 Like

While testing in 8.3.5 might change behavior as there have been significant changes to how resources and tags are managed, I am having a hard time replicating anything close to this in 8.3.3.

My test strategy was as follows:

  1. I have 30k tags on my Gateway setup with 100 tags per folder in 300 folders.
  2. I have run a script similar to the following in a Gateway, Vision, and Designer Script console context:
logger = system.util.getLogger('Vision Tag Read')
tag_name = 'Script Created {0}'
base_folder = '[default]Scripts'
results = system.tag.browse(base_folder, {'recursive': True, 'tagType': 'AtomicTag'}).results
tags = [str(result['fullPath']) for result in results]  

logger.info('Starting Read')
start_time = system.date.now()
a = system.tag.readBlocking(tags)
end_time = system.date.now()
logger.info('Finished Reading {0} values in: {1}ms'.format(len(a), system.date.millisBetween(start_time, end_time)))

Every single test run with 30k tags is coming back around ~1s so there is likely more going on that we will need to dive into.

1 Like

Did you guys both test against locally running gateways with a designer opened locally? I need to get more details from who set it up for my case, but I believe the gateway is running inside a vm in an on prem server. However I'm connected into a VPN from home to access it, launching a designer on my laptop locally. However I have done this before in 8.1, similar network architecture including vpn, and it’s been fine.

Edit: I'll try rdp into the server today and see if it’s the same running designer local on the gateway box

I was explicitly testing with a designer not on the same system as my Gateway just because I know that definitely could be a factor.

I am curious about the VM aspect of what you are seeing. Does the Gateway perform slowly in other ways (like loading the login screen or creating/editing tags)? Internally I am trying to track down something similar that is happening with a VM I have been using where everything behaves completely normal when I move it to a different environment.

This gateway will be part of 5, where this one is just hosting a few tag providers, so it’s very barebones.

I’ve just RDP’d directly onto the gateway and tried the script from there and same thing, timed out.

Crucial info below:

I tried a very simple script to get all tag paths from the provider and read them (92k tags) and it was quick.

The difference in my script is that i’m reading properties of tags like “valueSource”. As soon as I try to read properties, it times out.

Works, fast:

tagPaths = system.tag.browse(path='[FE001]', filter={'recursive': True, 'tagType': 'AtomicTag'})
len(tagPaths)
a = system.tag.readBlocking(str(t['fullPath']) for t in tagPaths)

Doesn’t work, times out:

tagPaths = system.tag.browse(path='[FE001]', filter={'recursive': True, 'tagType': 'AtomicTag'})
len(tagPaths)
a = system.tag.readBlocking(str(t['fullPath'])+'.valueSource' for t in tagPaths)

(appended “.valueSource” to the tagPath)

Use system.tag.query() and have it report all the properties of interest. One call, fastest possible results.

You’re not wrong! This script was from a while ago when the tag report tool didn’t exist. There are instances where you can’t use tag.query such as alarm configuration that has bindings for their values – query returns the expression rather than the evaluated value, but I wouldn't be using this particular script for those anyway..

Regardless though, better to fix a bug if there is one

1 Like

I have reproduced the issue Nick was seeing with system.tag.readBlocking being slow and this issue is resolved with changes in 8.3.5 (can be tested in the nightly).

On a completely unrelated note, if anyone is curious about the issue I was talking about with my VM instance not handling network requests at the same speed as my local system; it was a combination of the Resolve Client Hostnames setting being enabled on the Network.Network Settings.Web Server page and the following Java bug: https://bugs.openjdk.org/browse/JDK-6450279

2 Likes