8.1.33+ OPC Tag Writes Change

Ignition
1

I recently upgraded a gateway to 8.1.34, from 8.1.27. I saw 8.1.34 was pulled, and another upgrade to 8.1.35 did not change things...

A gateway tag change script, in which I use a for loop to read (40) memory tag values, and then write (40) PLC OPC Tags (Omron FINS driver). This is done 30 times, i.e. for step in range(1,31):

This is a recipe send operation.
Historically, this took ~25 seconds to complete as I have the recipe tags on a slower rate tag group.
One could watch the device driver stats on the gateway spike their overload % over time as the recipe tags were being written. Two tag groups default at 500ms, and the aforementioned recipe group at 3000ms. Just over 2000 tags in total 'monitored item count'.

After the upgrade, it was taking ~2.5 minutes.
And watching the device drive stats page, no spike in Overload% was seen.

Working a ticket with inductive, I am informed that...

...there has been a change in the logic of the OPC writes in batches...those were probably getting batched, but now in version 8.1.33+, they are not...

I looked over the release notes for 8.1.33 but do not see what I'd assume is a reference to this change.

It is suggested that I get rid of my for loop, to submit the writes (1200 total) in a single call vs. (40) called (30) times. Which I find somewhat lacking in code compactness / efficiency.

Surely other folks will be seeing this?

Thoughts?

I was not waiting for a fix, I downgraded the gateway to 8.1.27, and have re-done changes made since the upgrade. Just curious about it. In my case it seems like a big change.

1 Like
2

So it wasn't just my imagination... :thinking:

I saw the same 'slower' writes last week with the system.tag.writeBlocking, when I tested the upgrade to 8.1.34...
I didn't look any deeper into it, just 'downgraded' back to 8.1.28...

3

I'm not sure, since writeBlocking has to wait for the result it can't be batched for you in the background like writeAsync can in all cases. You should look into this more.

4

The code should be the same length and more obviously efficient because you aren't relying on undocumented batching magic.

1 Like
5

Both of you can turn these loggers on to try and diagnose whether batching is the issue or not:

  • Tags.Opc.Writes - TRACE
  • tags.execution.batchoperations - TRACE

https://docs.inductiveautomation.com/display/DOC81/Diagnostics+-+Logs#DiagnosticsLogs-ChangingLoggingLevels

There is still some degree of batching, it just depends what scope and threads the disparate write calls are made from.

e.g. this never batched for you (@zxcslo ):

	system.tag.writeBlocking(["L1"], [1])
	system.tag.writeBlocking(["L2"], [2])
	system.tag.writeBlocking(["L3"], [3])

but this did, and still does:

	system.tag.writeAsync(["L1"], [1])
	system.tag.writeAsync(["L2"], [2])
	system.tag.writeAsync(["L3"], [3])
1 Like
6

I'm new here, as such I am struggling to understand 'same length' comment. So please treat my scribbles like a newbie talking....

I was just concerned with lines of text in the script when I referred to compactness.

The script builds tag paths programmatically using the for loop's index integer. One line per path.
So 80 paths = 80 lines of text.

Getting rid of that, the suggestion from support means 2400 unique paths / 2400 lines. Do-able, but waiting for a time to engage in the effort just to see if it's a viable path for a future update attempt.

This user completely unaware of undocumented batching magic. So not aware I was relying on it. Regardless, the upgrade made the recipe transfer too long for production to sustain (in my opinion, never actually tried it once found).

7

You're already using a loop. You're practically there. Define a list for the paths and values outside the loop. Inside the loop, append paths and values to those lists.

When the loop is done, make a single write call with all the paths and values.

But please, feel free to pursue the troubleshooting so we can see if batching is even the issue.

8

I know nothing about batching (I am not even sure what that means)...

I have a script where I measure, how long it would take for one writeBlocking to write a bunch of tags...
In v8.1.28 it takes 30-50ms to write. On 8.1.34 was 1000-1500ms.
That's all saw.

I remember that I tried 8.1.34 to try this 'new' feature about Tag reference...
And I think that when I enabled Tag Reference Tracker Store all of that 'slow writes' started.
But when I disabled the Tag Reference Tracker Store again, it was no better, so I downgraded back to 8.1.28...

9

Probably nothing to do with batching.

If you're not willing to troubleshoot it and open a ticket with support don't be surprised if nothing changes.

10

I guarantee if you post this script or this portion of your script here you'll have volunteers to improve it. There's a cadre of folks here who take it as a personal challenge to minimize string duplication in cases like this.

This is, again, somewhat separate from the core concern of a regression that Kevin's trying to get to the bottom of, but seriously, don't let this stop you from rewriting your script - regression or not, one write or read call in bulk is absolutely going to be significantly more efficient.

2 Likes
11

We're easily nerd-sniped.

3 Likes
12

Heh, I have the script, from his support ticket. Right now I'm more interested in figuring out why it's slower after upgrading. Based on the script and scope of execution it should still be a candidate for batching, unless the readBlocking he does each iteration is now happening quite a bit slower. Or something else is going on.

13

doh, Now I feel educated. Seems obvious in hind sight.

So I setup a second gateway at 8.1.35 for cut-n-pasting things into the downgraded 8.1.27. I can move the PLC to the second gateway and try this. But I really need to exercise all my scripts after edits, and version changes in advance of a site visit before I do that.

14

There is definitely something changed in the system.tag.writeBlocking between 8.1.33 and 8.1.34+:
Today I tried again...
Installed v 8.1.33 in windows 10 VM and run this script in script console:

Benchmark_8_1_33
Benchmark_8_1_331838×1334 166 KB

As you can see, the writeBlocking took around 120ms for 35 tags.

Then I upgraded to 8.1.35 and run the same script in the script console again:

Benchmark_8_1_35
Benchmark_8_1_351618×1351 175 KB

This time writeBlocking took around 2700ms!!! That's 22x increase...

In the wrapper.log file you can see the difference (after seting Tags.Opc.Writes - TRACE and tags.execution.batchoperations - TRACE) between writing in 8.1.35 (2023/12/15 8:46:26) and 8.1.33 (2023/12/15 8:52:39)...
wrapper.zip (256.6 KB)

This is 8.1.35:

INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,STRING400.48, writes size=1, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | T [t.e.batchoperations           ] [07:46:26]: Requesting execution for 'OpcWriteBatch/Ignition OPC UA Server/277/OpcWriteBatch' with 100 ms delay writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Beginning execution of 'OpcWriteBatch/Ignition OPC UA Server/277' 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Executing, writes size=1, read-after-writes size=0 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution finished, took 6ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,D450, writes size=1, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Execution of 'OpcWriteBatch/Ignition OPC UA Server/277' completed in 7 ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Rescheduling task due to new changes. 
INFO   | jvm 1    | 2023/12/15 08:46:26 | T [t.e.batchoperations           ] [07:46:26]: Requesting execution for 'OpcWriteBatch/Ignition OPC UA Server/277/OpcWriteBatch' with 100 ms delay 
INFO   | jvm 1    | 2023/12/15 08:46:26 | T [t.e.batchoperations           ] [07:46:26]: Requesting execution for 'cfg/BatchConfigOperation' with 100 ms delay provider=tagprovider
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Beginning execution of 'OpcWriteBatch/Ignition OPC UA Server/277' 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Executing, writes size=1, read-after-writes size=0 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution finished, took 4ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Execution of 'OpcWriteBatch/Ignition OPC UA Server/277' completed in 4 ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.0, writes size=1, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Rescheduling task due to new changes. 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | T [t.e.batchoperations           ] [07:46:26]: Requesting execution for 'OpcWriteBatch/Ignition OPC UA Server/277/OpcWriteBatch' with 100 ms delay 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Beginning execution of 'cfg' 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Execution of 'cfg' completed in 8 ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Beginning execution of 'OpcWriteBatch/Ignition OPC UA Server/277' 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Executing, writes size=1, read-after-writes size=0 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution finished, took 4ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Execution of 'OpcWriteBatch/Ignition OPC UA Server/277' completed in 5 ms 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.1, writes size=1, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Rescheduling task due to new changes. 
INFO   | jvm 1    | 2023/12/15 08:46:26 | T [t.e.batchoperations           ] [07:46:26]: Requesting execution for 'OpcWriteBatch/Ignition OPC UA Server/277/OpcWriteBatch' with 100 ms delay 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/277, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=FDDF6828
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [t.e.batchoperations           ] [07:46:26]: Beginning execution of 'OpcWriteBatch/Ignition OPC UA Server/277' 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Executing, writes size=1, read-after-writes size=0 
INFO   | jvm 1    | 2023/12/15 08:46:26 | D [T.O.Writes                    ] [07:46:26]: Execution finished, took 4ms

and this is 8.1.33:

INFO   | jvm 1    | 2023/12/15 08:52:39 | T [t.e.batchoperations           ] [07:52:38]: Requesting execution for 'cfg/BatchConfigOperation' with 100 ms delay provider=tagprovider
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,STRING400.48, writes size=1, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | T [t.e.batchoperations           ] [07:52:39]: Requesting execution for 'OpcWriteBatch/Ignition OPC UA Server/178/OpcWriteBatch' with 100 ms delay writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,D450, writes size=2, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.0, writes size=3, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.1, writes size=4, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.2, writes size=5, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.3, writes size=6, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X454.4, writes size=7, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X455.0, writes size=8, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X455.1, writes size=9, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X455.2, writes size=10, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X455.3, writes size=11, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X455.4, writes size=12, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,X455.5, writes size=13, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,B456, writes size=14, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,REAL460, writes size=15, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,REAL464, writes size=16, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,REAL468, writes size=17, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,W472, writes size=18, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,W474, writes size=19, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,W476, writes size=20, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,W478, writes size=21, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,W480, writes size=22, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,REAL482, writes size=23, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,W486, writes size=24, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,B457, writes size=25, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Write added, nodeId=[Ignition OPC UA Server][s7_1500_cno]DB1,REAL500, writes size=26, read-after-writes size=0 writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution requested writeBatchId=OpcWriteBatch/Ignition OPC UA Server/178, provider=tagprovider, request-origin=127.0.0.1, session-user=admin, session-project=klscno4, session-id=4D5486E9
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [t.e.batchoperations           ] [07:52:39]: Beginning execution of 'cfg' 
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [t.e.batchoperations           ] [07:52:39]: Beginning execution of 'OpcWriteBatch/Ignition OPC UA Server/178' 
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Executing, writes size=26, read-after-writes size=0 
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [t.e.batchoperations           ] [07:52:39]: Execution of 'cfg' completed in 8 ms 
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [T.O.Writes                    ] [07:52:39]: Execution finished, took 15ms 
INFO   | jvm 1    | 2023/12/15 08:52:39 | D [t.e.batchoperations           ] [07:52:39]: Execution of 'OpcWriteBatch/Ignition OPC UA Server/178' completed in 15 ms
2 Likes
15

I added wrapper.zip with these set to my ticket.

16

Thanks, I think I figured out what's going on.

It's not the batching change - 8.1.33 also has the new batching change. It looks like a regression introduced by the Tag Reference Tracker work.

17

This is fixed and will be part of the 8.1.36 release.

4 Likes
18

Is this system.ooc.tagWriteBlocking or system.tag.writeBlocking or both?

19

Any writes in the "tag system" layer - so OPC tags, memory tags, would all be affected. The OPC system was not affected - system.opc.writeValues should work exactly the same as it did.

3 Likes