system.opc.writeValue slow?

aaron1 · October 26, 2020, 12:18am

Hi peeps,

I am running into an intermittent issue where sometimes a script executing system.opc.writeValue can take up to 20 odd seconds to execute and this can disrupt the production when it happens. All the script does is the following:

def HSK_Write(writeValue):
	
	WriteSuccess = -1
	server = "Ignition OPC-UA Server"
	path = "ns=1;s=[PLC]Global.Ignition_StatusUpdated"
	
	for i in range(3):
		try:
			returnQuality = system.opc.writeValue(server, path, writeValue)
			if returnQuality.isGood():
				system.tag.write("[default]Retry_Tags/Value_Update_Handshake", -99)			#-99 means write success
				WriteSuccess = -99
				break
		except:
			pass

	if WriteSuccess != -99:
		system.tag.write("[default]Retry_Tags/Value_Update_Handshake", writeValue)	#This triggers timer script for retries

The tag “Retry_Tags/Value_Update_Handshake” is only a memory tag so I wouldn’t imagine it will take long to write to that tag. There’s no sign of the server hardware overloading when this occurs either.

So just wondering if anyone has any suggestions on what I should be looking for in the gateway for fault finding/diagnostics or if there’s any suggestions on common practice that would bring down the time required to do an OPC write? As I thought using the system.opc.writeValue is generally faster than writing through scan classes.

Could it be a network issue or something on the PLC end?

The gateway version is 8.0.1 and the tag count on this specific device is only 44 tags.

Many thanks.

pturmel · October 26, 2020, 12:44am

My guess would be a network dropped packet followed by TCP retries. If the device is lightly loaded, there might be enough dead time that a random missed packet isn’t noticed quickly by the underlying TCP stack.

Kevin.Herron · October 26, 2020, 12:47am

Could also be that the device was reconnecting or re-browsing at the time. Maybe you can add some logging to this script that measures the execution time and logs when it starts and finishes, and then you can correlate slow executions with other things happening in the gateway logs.

aaron1 · February 4, 2025, 6:26am

@pturmel @Kevin.Herron
Hi guys,

Happy 2025.

Back at this after a few years as there is now a bit more incentive to try and put this one to bed this time round... Would really appreciate some pointers if possible to try and get to the bottom of this or any suggestions on any potential workaround...

The issue is still the same as described in the original post where occasionally we'd see the gateway script taking a long time to complete and it seems to be pointing to the subroutine where it executes the OPC write judging from the diagnostics we are logging to the wrapper log.

For example, below is a snip from the wrapper log when things are working fine:

INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Repack Check Starts
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Repack Check Complete
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Repack Update Cans Starts
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Repack Update Cans Done
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Repack Update Cases Starts
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Repack Update Product Done
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Product Insert Starts
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Product Insert Done
INFO   | jvm 1    | 2025/01/29 10:59:04 | ProdID = 266, ProdPK = 1879990, PO = 111000
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Starts
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Done
INFO   | jvm 1    | 2025/01/29 10:59:04 | ++++++++++  Product Write Debug ++++++++++Form Item List Starts
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Form Item List Done
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Can Update Starts
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Can Update Done
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Can Insert Starts
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Can Insert Done
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++OK List Insert Starts
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++OK List Insert Done
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Starts
INFO   | jvm 1    | 2025/01/29 10:59:05 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Done

vs. when this issue occurs:
(the delay between Repack Check Starts and Repack Check Complete is also new to me and I also want to say this could be tag read/write related rather than DB insert/update related as I am not seeing delay in DB transactions in other steps...)

INFO   | jvm 1    | 2025/01/29 10:50:38 | ++++++++++  Product Write Debug ++++++++++Repack Check Starts
INFO   | jvm 1    | 2025/01/29 10:50:38 | 0
INFO   | jvm 1    | 2025/01/29 10:50:58 | ++++++++++  Product Write Debug ++++++++++Repack Check Complete
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Repack Update Cans Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Repack Update Cans Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Repack Update Cases Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Repack Update Product Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Product Insert Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Product Insert Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ProdID = 248, ProdPK = 1879972, PO = 111000
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | 0
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Form Item List Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Form Item List Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Can Update Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Can Update Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Can Insert Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Can Insert Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++OK List Insert Starts
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++OK List Insert Done
INFO   | jvm 1    | 2025/01/29 10:50:59 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Starts
INFO   | jvm 1    | 2025/01/29 10:51:19 | Handshake Off Write Done
INFO   | jvm 1    | 2025/01/29 10:51:22 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Done

A few questions that I have at the moment are:

We have seen some tags (not all tags and not the handshake tag) from the same PLC that went into a unknown state and we had to right-click on the tags and restart them for them to come right. Could this be an indication that's pointing to the same cause as the issue with the slowness in OPC write? (eg. packets being dropped on the network)
Have attached a section of the wrapper log from when things running smoothly to when the issue started occurring. There are a few things in the log I don't quite understand what I am looking at and would like to get some expert opinions on....

A) I believe this is when I logged into Ignition and restarted those tags motioned above where they went into unknown state and looking at the log the issue with delay started occurring.

INFO   | jvm 1    | 2025/01/29 10:33:24 | ++++++++++  Product Write Debug ++++++++++Repack Check Starts
INFO   | jvm 1    | 2025/01/29 10:33:24 | ++++++++++  Product Write Debug ++++++++++Repack Check Complete
INFO   | jvm 1    | 2025/01/29 10:33:24 | ++++++++++  Product Write Debug ++++++++++Product Insert Starts
INFO   | jvm 1    | 2025/01/29 10:33:24 | ++++++++++  Product Write Debug ++++++++++Product Insert Done
INFO   | jvm 1    | 2025/01/29 10:33:24 | ProdID = 244, ProdPK = 1879968, PO = 111000
INFO   | jvm 1    | 2025/01/29 10:33:24 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Starts
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Done
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Form Item List Starts
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Form Item List Done
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Can Update Starts
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Can Update Done
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++OK List Insert Starts
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++OK List Insert Done
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Starts
INFO   | jvm 1    | 2025/01/29 10:33:25 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Done
INFO   | jvm 1    | 2025/01/29 10:33:25 | Handshake Off Write Done
INFO   | jvm 1    | 2025/01/29 10:34:44 | I [p.DesignSession               ] [21:34:44]: Socket connected to session. pageId=session-props session-project=Tracking_Global
INFO   | jvm 1    | 2025/01/29 10:38:06 | I [o.a.w.r.PropertiesFactory     ] [21:38:06]: Loading properties files from jar:file:/C:/Program%20Files/Inductive%20Automation/Ignition/lib/core/gateway/wicket-core-6.1.1.jar!/org/apache/wicket/Application.properties with loader org.apache.wicket.resource.IsoPropertiesFilePropertiesLoader@715982a 
INFO   | jvm 1    | 2025/01/29 10:38:06 | I [o.a.w.r.PropertiesFactory     ] [21:38:06]: Loading properties files from jar:file:/C:/Program%20Files/Inductive%20Automation/Ignition/lib/core/gateway/wicket-extensions-6.1.1.jar!/org/apache/wicket/extensions/Initializer.properties with loader org.apache.wicket.resource.IsoPropertiesFilePropertiesLoader@715982a 
INFO   | jvm 1    | 2025/01/29 10:40:37 | I [d.CompactLogixDriver          ] [21:40:37]: [PLC_A] Processor edit number changed from 23297 to -1. device-name=PLC_A
INFO   | jvm 1    | 2025/01/29 10:40:37 | I [d.CompactLogixDriver          ] [21:40:37]: [PLC_A] Processor edit number changed from -1 to 23297. device-name=PLC_A
INFO   | jvm 1    | 2025/01/29 10:40:37 | I [c.i.x.d.a.r.ABControlLogixBrowseRequest] [21:40:37]: [PLC_A] Creating browse request using LOW priority. 
INFO   | jvm 1    | 2025/01/29 10:40:53 | I [c.i.x.d.a.r.ABControlLogixBrowseRequest] [21:40:53]: [PLC_A] Creating browse nodes. 
INFO   | jvm 1    | 2025/01/29 10:40:53 | I [c.i.x.d.a.r.ABControlLogixBrowseRequest] [21:40:53]: [PLC_A] Browse complete. 
INFO   | jvm 1    | 2025/01/29 10:40:53 | I [d.CompactLogixDriver          ] [21:40:53]: [PLC_A] Browse complete. device-name=PLC_A
INFO   | jvm 1    | 2025/01/29 10:40:53 | I [d.CompactLogixDriver          ] [21:40:53]: [PLC_A] Updating tagManager with edit version 23297 with 2081 tags device-name=PLC_A
INFO   | jvm 1    | 2025/01/29 10:40:54 | E [d.C.ABControlLogixWriteRequest] [21:40:54]: Error writing string value for tag Global.Ignition_TrackingFixed.STRING. Value is null or not a string. device-name=PLC_A
INFO   | jvm 1    | 2025/01/29 10:40:54 | E [LegacyScripting[system_util_tag]] [21:40:54]: Error writing tags
INFO   | jvm 1    | 2025/01/29 10:40:54 | Error writing to tag '[default]URL_Check/PLC_A/Ignition_TrackingFixed': Bad
INFO   | jvm 1    | 2025/01/29 10:40:54 |  
INFO   | jvm 1    | 2025/01/29 10:42:25 | 0
INFO   | jvm 1    | 2025/01/29 10:42:32 | 0
INFO   | jvm 1    | 2025/01/29 10:42:48 | 0
INFO   | jvm 1    | 2025/01/29 10:43:16 | 0
INFO   | jvm 1    | 2025/01/29 10:43:34 | 0
INFO   | jvm 1    | 2025/01/29 10:43:53 | 0
INFO   | jvm 1    | 2025/01/29 10:44:11 | 0
INFO   | jvm 1    | 2025/01/29 10:44:30 | 0
INFO   | jvm 1    | 2025/01/29 10:44:59 | 0
INFO   | jvm 1    | 2025/01/29 10:45:23 | 0
INFO   | jvm 1    | 2025/01/29 10:45:25 | 0
INFO   | jvm 1    | 2025/01/29 10:45:28 | 
INFO   | jvm 1    | 2025/01/29 10:45:29 | 
INFO   | jvm 1    | 2025/01/29 10:45:29 | 
INFO   | jvm 1    | 2025/01/29 10:45:29 | ++++++++++  Product Write Debug ++++++++++Repack Check Starts
INFO   | jvm 1    | 2025/01/29 10:45:47 | ++++++++++  Product Write Debug ++++++++++Repack Check Complete
INFO   | jvm 1    | 2025/01/29 10:45:48 | ++++++++++  Product Write Debug ++++++++++Repack Update Cans Starts
INFO   | jvm 1    | 2025/01/29 10:45:48 | 0
INFO   | jvm 1    | 2025/01/29 10:46:07 | ++++++++++  Product Write Debug ++++++++++Repack Update Cans Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Repack Update Cases Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Repack Update Product Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Product Insert Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Product Insert Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ProdID = 245, ProdPK = 1879969, PO = 111000
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Find Existing Tracking Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Form Item List Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Form Item List Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Can Update Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Can Update Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Can Insert Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Can Insert Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++OK List Insert Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++OK List Insert Done
INFO   | jvm 1    | 2025/01/29 10:46:08 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Starts
INFO   | jvm 1    | 2025/01/29 10:46:08 | 0
INFO   | jvm 1    | 2025/01/29 10:46:29 | Handshake Off Write Done
INFO   | jvm 1    | 2025/01/29 10:46:29 | ++++++++++  Product Write Debug ++++++++++Product Insert Handshake Done

B) Not long after the issue started happening, from timestamp 2025/01/29 10:54:05 to 2025/01/29 10:55:10 there is a whole lot log related to apache.wicket which I am not sure if these are somewhat related.

INFO   | jvm 1    | 2025/01/29 10:54:05 | W [o.a.w.p.PageAccessSynchronizer] [21:54:05]: Thread 'webserver-106155' failed to acquire lock to page with id '7', attempted for 1 minutes out of allowed 1 minute. The thread that holds the lock has name 'webserver-106118'. 
INFO   | jvm 1    | 2025/01/29 10:54:05 | W [o.a.w.p.PageAccessSynchronizer] [21:54:05]: "webserver-106118" prio=5 tid=106118 state=RUNNABLE  
INFO   | jvm 1    | 2025/01/29 10:54:05 | org.apache.wicket.util.lang.Threads$ThreadDump: null
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.io.WinNTFileSystem.getBooleanAttributes(Native Method)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.io.File.exists(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/jdk.internal.loader.URLClassPath$FileLoader.getResource(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/jdk.internal.loader.URLClassPath$FileLoader.findResource(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/jdk.internal.loader.URLClassPath.findResource(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.net.URLClassLoader$2.run(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.net.URLClassLoader$2.run(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.security.AccessController.doPrivileged(Native Method)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.net.URLClassLoader.findResource(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.webapp.WebAppClassLoader.getResource(WebAppClassLoader.java:434)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.core.util.resource.ClassPathResourceFinder.getResourceStreamWithClassLoader(ClassPathResourceFinder.java:93)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.core.util.resource.ClassPathResourceFinder.find(ClassPathResourceFinder.java:72)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.core.util.resource.locator.ResourceStreamLocator.locate(ResourceStreamLocator.java:130)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//com.inductiveautomation.ignition.gateway.IgnitionGateway$3.locate(IgnitionGateway.java:789)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.core.util.resource.locator.ResourceStreamLocator.locate(ResourceStreamLocator.java:164)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.core.util.resource.locator.caching.CachingResourceStreamLocator.locate(CachingResourceStreamLocator.java:122)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.DefaultMarkupResourceStreamProvider.getMarkupResourceStream(DefaultMarkupResourceStreamProvider.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.MarkupFactory.getMarkupResourceStream(MarkupFactory.java:320)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.MarkupCache.getMarkup(MarkupCache.java:296)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.MarkupFactory.getMarkup(MarkupFactory.java:236)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.MarkupFactory.getMarkup(MarkupFactory.java:194)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.MarkupContainer.getAssociatedMarkup(MarkupContainer.java:401)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.MarkupContainer.getAssociatedMarkupStream(MarkupContainer.java:368)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.html.panel.AssociatedMarkupSourcingStrategy.renderHeadFromAssociatedMarkupFile(AssociatedMarkupSourcingStrategy.java:244)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.html.panel.AssociatedMarkupSourcingStrategy.renderHead(AssociatedMarkupSourcingStrategy.java:220)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Component.renderHead(Component.java:2676)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.ChildFirstHeaderRenderStrategy$1.component(ChildFirstHeaderRenderStrategy.java:85)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:96)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:87)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.DeepChildFirstVisitor.visit(DeepChildFirstVisitor.java:51)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.ChildFirstHeaderRenderStrategy.renderChildHeaders(ChildFirstHeaderRenderStrategy.java:78)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.renderStrategy.ChildFirstHeaderRenderStrategy.renderHeader(ChildFirstHeaderRenderStrategy.java:57)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.html.internal.HtmlHeaderContainer.onComponentTagBody(HtmlHeaderContainer.java:170)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.html.panel.DefaultMarkupSourcingStrategy.onComponentTagBody(DefaultMarkupSourcingStrategy.java:71)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Component.internalRenderComponent(Component.java:2535)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.MarkupContainer.onRender(MarkupContainer.java:1491)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Component.internalRender(Component.java:2365)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Component.render(Component.java:2293)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.MarkupContainer.renderNext(MarkupContainer.java:1388)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.MarkupContainer.renderAll(MarkupContainer.java:1553)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Page.onRender(Page.java:884)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.markup.html.WebPage.onRender(WebPage.java:142)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Component.internalRender(Component.java:2365)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Component.render(Component.java:2293)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.Page.renderPage(Page.java:1021)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.handler.render.WebPageRenderer.renderPage(WebPageRenderer.java:116)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.handler.render.WebPageRenderer.respond(WebPageRenderer.java:244)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.core.request.handler.RenderPageRequestHandler.respond(RenderPageRequestHandler.java:165)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:814)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:64)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:97)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.cycle.RequestCycle.execute(RequestCycle.java:253)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:210)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:281)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:188)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.apache.wicket.protocol.http.WicketFilter.doFilter(WicketFilter.java:245)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//com.inductiveautomation.ignition.gateway.bootstrap.GatewayFilter.doFilter(GatewayFilter.java:74)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:61)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.Server.handle(Server.java:530)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at app//org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at java.base@11.0.2/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2025/01/29 10:54:05 | E [o.a.w.DefaultExceptionMapper  ] [21:54:05]: Unexpected error occurred 
INFO   | jvm 1    | 2025/01/29 10:54:05 | org.apache.wicket.page.CouldNotLockPageException: Could not lock page 7. Attempt lasted 1 minute
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.page.PageAccessSynchronizer.lockPage(PageAccessSynchronizer.java:171)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.page.PageAccessSynchronizer$2.getPage(PageAccessSynchronizer.java:256)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.DefaultMapperContext.getPageInstance(DefaultMapperContext.java:148)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.core.request.handler.PageProvider.getStoredPage(PageProvider.java:306)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.core.request.handler.PageProvider.resolvePageInstance(PageProvider.java:261)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.core.request.handler.PageProvider.getPageInstance(PageProvider.java:166)
INFO   | jvm 1    | 2025/01/29 10:54:05 | 	at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.getPage(ListenerInterfaceRequestHandler.java:96)

*C) There is also logs in the mix related to PLC_B where it was also having the same issue at the time.

INFO   | jvm 1    | 2025/01/29 10:54:36 | I [d.CompactLogixDriver          ] [21:54:36]: [PLC_B] Processor edit number changed from 4866 to 6402. device-name=PLC_B
INFO   | jvm 1    | 2025/01/29 10:54:37 | I [c.i.x.d.a.r.ABControlLogixBrowseRequest] [21:54:36]: [PLC_B] Creating browse request using LOW priority. 
INFO   | jvm 1    | 2025/01/29 10:54:44 | W [o.a.w.p.PageAccessSynchronizer] [21:54:44]: Thread 'webserver-106005' failed to acquire lock to page with id '7', attempted for 1 minutes out of allowed 1 minute. The thread that holds the

the handshake tag that we write to using system.opc.writeValue() is also being scanned as a tag with 200ms scan time. Would this have an impact on writing to it via opcWrite()?
If the issue is relate to lightly loaded PLC and dropped packet, how could we approach in solving this issue?

Any suggestions would be much appreciated!
Wrapper Log.txt (143.7 KB)

pturmel · February 4, 2025, 12:26pm

You should alter your logging associated with system.opc.writeValues() to capture the list of quality codes that is returned. Scan them for non-good responses and correlate to the OPC Item Path that caused it. Report those quality code/OPC Item Path pair. (Any entry that fails due to a dropped packet will generate a stall.)

aaron1 · February 4, 2025, 7:47pm

Hi Phil,

Thank you for your reply, will start adding these to the logs.

So say we prove that it is due to packets being dropped on the network and not being noticed quickly, how could we go about improving this? Is it because I am writing just a Boolean value and the packet is too small? Am I better of writing the value using normal tag writes (system.tag.writeSynchronous etc) or write to more tags at the same time to increase packet size?

Thanks.