First ReadValue after Subscribe or inside Notification is much slower

[Nick135]

Type of Issue

• [x] Bug
• [ ] Enhancement
• [ ] Compliance
• [ ] Question
• [ ] Help wanted

Describe the Issue

First or second read request after subscribe is much slower as other requests. Also the first read request on notification is much slower.

To Reproduce Steps to reproduce the behavior:

1. Subscribe to node

2. ReadValue

3. Subscribe to node

4. ReadValue inside of the notification

Expected behavior Same performance as other requests

Log output

ReadVarOnStart: False | 0,008s
ReadVarOnStart: True | 0,012s
ReadVarOnStart: True | 0,003s
ReadVarOnStart: True | 0,003s
ReadVarOnStart: True | 0,008s
ReadVarOnStart: False | 0,006s
ReadVarOnStart: False | 0,003s
ReadVarOnStart: False | 0,003s
ReadVarOnStart: False | 0,009s
ReadVarOnStart: True | 0,005s
ReadVarOnStart: True | 0,003s
ReadVarOnStart: True | 0,004s
ReadVarOnStart: False | 0,011s
ReadVarOnStart: False | 0,003s
ReadVarOnStart: False | 0,004s
ReadVarOnStart: False | 0,004s
ReadVarOnStart: True | 0,010s
ReadVarOnStart: True | 0,003s
ReadVarOnStart: True | 0,003s
ReadVarOnStart: True | 0,004s
ReadVarOnStart: Average=0,005s | Min=0,003s | Max=0,012s

//Subscribe to Node
MonitoredItem_Notification: Name=0c83f4df-3d5b-497c-89f9-be342cc6050c, Value=140

ReadVarAfterSubscribe: False | 0,004s
ReadVarAfterSubscribe: False | 0,195s
ReadVarAfterSubscribe: False | 0,004s
ReadVarAfterSubscribe: False | 0,004s
ReadVarAfterSubscribe: True | 0,010s
ReadVarAfterSubscribe: True | 0,003s
ReadVarAfterSubscribe: True | 0,003s
ReadVarAfterSubscribe: True | 0,004s
ReadVarAfterSubscribe: False | 0,010s
ReadVarAfterSubscribe: False | 0,004s
ReadVarAfterSubscribe: False | 0,005s
ReadVarAfterSubscribe: True | 0,009s
ReadVarAfterSubscribe: True | 0,004s
ReadVarAfterSubscribe: True | 0,004s
ReadVarAfterSubscribe: False | 0,010s
ReadVarAfterSubscribe: False | 0,003s
ReadVarAfterSubscribe: False | 0,004s
ReadVarAfterSubscribe: False | 0,009s
ReadVarAfterSubscribe: True | 0,004s
ReadVarAfterSubscribe: True | 0,004s
ReadVarAfterSubscribe: Average=0,015s | Min=0,003s | Max=0,195s

MonitoredItem_Notification: Name=0c83f4df-3d5b-497c-89f9-be342cc6050c, Value=150

//ReadValue inside notification
ValueChanged: False | 0,145s
ValueChanged: True | 0,012s
ValueChanged: True | 0,006s
ValueChanged: True | 0,003s
ValueChanged: False | 0,011s
ValueChanged: False | 0,004s
ValueChanged: False | 0,004s
ValueChanged: True | 0,011s
ValueChanged: True | 0,004s
ValueChanged: True | 0,004s
ValueChanged: Average=0,020s | Min=0,003s | Max=0,145s

MonitoredItem_Notification: Name=0c83f4df-3d5b-497c-89f9-be342cc6050c, Value=160

//ReadValue inside notification
ValueChanged: True | 0,158s
ValueChanged: True | 0,003s
ValueChanged: True | 0,003s
ValueChanged: False | 0,011s
ValueChanged: False | 0,004s
ValueChanged: False | 0,004s
ValueChanged: True | 0,012s
ValueChanged: True | 0,004s
ValueChanged: True | 0,004s
ValueChanged: False | 0,011s
ValueChanged: Average=0,021s | Min=0,003s | Max=0,158s

MonitoredItem_Notification: Name=0c83f4df-3d5b-497c-89f9-be342cc6050c, Value=500

//ReadValue inside notification
ValueChanged: True | 0,198s
ValueChanged: True | 0,004s
ValueChanged: True | 0,004s
ValueChanged: True | 0,008s
ValueChanged: False | 0,005s
ValueChanged: False | 0,003s
ValueChanged: False | 0,004s
ValueChanged: True | 0,012s
ValueChanged: True | 0,003s
ValueChanged: True | 0,004s
ValueChanged: Average=0,024s | Min=0,003s | Max=0,198s

Environment (please complete the following information):

• OS: Win10
• Development environment: Visual Studio 2019 16.9.1
• Runtime: .NET 4.6.2
• OPC Package Release Version 1.4.365.48
• Component: Opc.Ua.Client
• Server: S71500 (1517TF-3 PN/DP)
• Client: Opc.Ua.Client

[Nick135]

I made a simple test with an other OPC UA Client Lib and measure the time between value change and get response inside the plc. With the other lib there is no lack of 140-200ms.

[AlinMoldovean]

@Nick135 ,

Does the issue reproduce also against the ReferenceServer of this repository? Or only with S71500 Server? Could you please provide the sample code used to test this issue?

[Nick135]

I only test with the S71500 Server.

[Nick135]

@AlinMoldovean I can´t test with the ReferenceServer of this repo. (UA-.NETStandard-Samples) The NetCore Console UA-Server don´t accept the certificate from UAExpert and the WinForm UA-Server works with UAExpert, but not with my console example. Problem is always the certificate. This Library is very complicated in this part.

I don´t have the delay problem with this UA-Client and S71500 Server. https://github.com/convertersystems/opc-ua-client

[mregen]

Checking back @Nick135 if this could be related to S7. Have you tried registered Read to improve the read perf? It is also unclear to me:

• The measured time, what is measured?
• Why do you read a value inside a notification, assuming its a subscription notification? Normally you get the changed vaue in the publishrequest, so a seperate Read is not necessary?
• To drill down where the read request is delayed, you can take a wireshark dump if its a processing issue on client or server side.

[Nick135]

@mregen I don´t know how to do registered Read. But the normal read performance of 3-12ms is good enough.

About your Questions.

• "The measured time, what is measured?"

  I measured the time of a read request

  s0 = Stopwatch.StartNew();
  var a = client.ReadVariable(nodeIdCyclic);
  s0.Stop();

• "Why do you read a value inside a notification, assuming its a subscription notification? Normally you get the changed vaue in the publishrequest, so a seperate Read is not necessary?"

  I subscripe to a PLC variable e.g. "NewCommand" Then I read or write a complete Struct from/to the plc with the job info. For this problem, I only read a single variable in a loop as the behavior is the same but easier to understand and reproduce.

• "To drill down where the read request is delayed, you can take a wireshark dump if its a processing issue on client or server side."

  Wireshark: Issue1397.zip