Avatar

Please consider registering
guest

sp_LogInOut Log In sp_Registration Register

Register | Lost password?
Advanced Search

— Forum Scope —




— Match —





— Forum Options —





Minimum search word length is 3 characters - maximum search word length is 84 characters

sp_Feed Topic RSS sp_TopicIcon
Again Slow Browse - due to server redirect?
March 7, 2017
15:49, EET
Avatar
in-fke
Member
Members
Forum Posts: 36
Member Since:
June 8, 2016
sp_UserOfflineSmall Offline

I was not sure if this is related to one the following topics – so I thought I’d open a new one:
http://forum.prosysopc.com/for…..tesnodeid/
http://forum.prosysopc.com/for…..ow-browse/

We are browsing via. addressSpace.browse() and addressSpace.getNode() (we call getNode() only if we hit a UAVariable), using binary opc.tcp
On different servers, the average per Node may be 9ms. That may be OK.

But:
Browsing a SIMATIC S7-1500 (?) the average per Node is ~ 220ms. This is using binary opc.tcp and SecurityPolicy NONE.
What may be relevant is during connection, we get the following message:
client.UaClient:? Using an alternate endpoint URL ‘opc.tcp://B:4840’ instead of the requested ‘opc.tcp://A:4840’
where A and B are IP addresses.
Could this indicate some performance issue in the server, where everything is redirected to B? We are physically connected to A.

We shot some call stacks to see where the VM is “waiting”, and this is what we got:
#78 daemon prio=5 os_prio=0 tid=0x0000000018d28000 nid=0x118c waiting on condition [0x00000000259cc000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
– parking to wait for (a java.util.concurrent.Semaphore$NonfairSync)
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(Unknown Source)
at java.util.concurrent.Semaphore.tryAcquire(Unknown Source)
at org.opcfoundation.ua.transport.impl.AsyncResultImpl.waitForResult(Unknown Source)
at org.opcfoundation.ua.transport.tcp.io.SecureChannelTcp.serviceRequest(Unknown Source)
at org.opcfoundation.ua.transport.tcp.io.SecureChannelTcp.serviceRequest(Unknown Source)
at org.opcfoundation.ua.application.SessionChannel.serviceRequest(Unknown Source)
at org.opcfoundation.ua.transport.ChannelService.Read(Unknown Source)
at com.prosysopc.ua.client.UaClient.doRead(Unknown Source)
at com.prosysopc.ua.client.UaClient.read(Unknown Source)
at com.prosysopc.ua.client.UaClient.readAttributes(Unknown Source)
at com.prosysopc.ua.client.UaClient.readAttributes(Unknown Source)
at com.prosysopc.ua.client.AddressSpace.readAttributes(Unknown Source)
– locked (a com.prosysopc.ua.client.AddressSpace)
at com.prosysopc.ua.client.AddressSpace.readNode(Unknown Source)
– locked (a com.prosysopc.ua.client.AddressSpace)
at com.prosysopc.ua.client.AddressSpace.getNode(Unknown Source)
– locked (a com.prosysopc.ua.client.AddressSpace)
at

May be a different topic, we get some sporadic log messages from the OPC UA Stack, like:
INFO [TcpConnection/Read] binary.BinaryDecoder:? Failed to decode ExtensionObject: org.opcfoundation.ua.encoding.DecodingException: Bad_DecodingError (code=0x80070000, description=”Cannot decode null”)

We are using Client 2.2.6-708 and OPC UA Stack 1.02.337.10

March 7, 2017
16:49, EET
Avatar
Heikki Tahvanainen
Member
Members
Forum Posts: 402
Member Since:
April 17, 2013
sp_UserOfflineSmall Offline

Hi,

Thank you for the very detailed question. You are correct that normal round trip times are something in the range of milliseconds and 200 milliseconds is a comparatively long time for a service call. Of course network can cause some ‘natural’ delay and the contents of some specific service call can be demanding on the server application, but 200 milliseconds for a browse call on average is a long time.

The AsyncResultImpl.waitForResult is the ‘normal’ waiting location which shows that the client application is waiting to receive an asynchronous response from the server. So, based on this information, it sounds like the server is just simply slow to respond.

The line “Using an alternate endpoint URL ‘opc.tcp://B:4840’ instead of the requested ‘opc.tcp://A:4840’” is informational and just tells that OPC UA server application has been configured to use a certain ip-address even though you contacted with another address. It does not mean that the service calls are actually redirected to another server.

The DecodingErrors may be something more severe, but they are probably not directly related to this performance problem.

Based on this information the most probable reason for the slow reads is the server application. To inspect the performance problem further, you can try reproducing the long response times with another UA client application or logging the communication with Wireshark and then analyzing the traffic timestamps (https://prosysopc.com/blog/opc-ua-wireshark/).

March 7, 2017
18:02, EET
Avatar
in-fke
Member
Members
Forum Posts: 36
Member Since:
June 8, 2016
sp_UserOfflineSmall Offline

Wow Heikki, thanks for the super fast reply.
Based on your information, I was able to get some more details from our customer. Turns out there is some kind of router between our client and the actual server.
That explains the notice about the endpoint.

I dug down into the product a bit more and found this:
https://cache.industry.siemens.com/dl/files/901/109737901/att_898965/v3/109737901_OPC_UA_Client_S7-1500_DOKU_V10_en.pdf

On page 9 a setting is mentioned, which happens to have a preset to 200ms (which may relate to our browse performance).
“Minimum publishing interval”:
This value determines at what minimal intervals the OPC UA server is allowed to
send data to a client via OPC UA subscriptions.

Though the description mentions only “subscriptions” – it may be that this limit relates to any client response?
Now I wonder how on earth I could place a support call at Siemens to figure this one out…

March 7, 2017
18:25, EET
Avatar
Heikki Tahvanainen
Member
Members
Forum Posts: 402
Member Since:
April 17, 2013
sp_UserOfflineSmall Offline

Hi,

Thank you for the information. However, the minimum publishing interval is not probably related to this issue in any way. As you already have noticed, it’s related to subscriptions.

What kind of a network is there between your client and the server? If you try to ping the Simatic device, how long does it take?

March 14, 2017
12:46, EET
Avatar
in-fke
Member
Members
Forum Posts: 36
Member Since:
June 8, 2016
sp_UserOfflineSmall Offline

We now changed our “browser” from using:
browse()
getNode()
to:
browse()
read()
where we browse first, then batch read the attribute we need to know for UaVariable (

This works well for two types of OPC UA Servers, but the S7-1500 again does not like us, the OPC UA Client runs into

java.lang.ArrayIndexOutOfBoundsException: 0
at com.prosysopc.ua.client.UaClient.read(Unknown Source)
at

On another note, we then get flooded with log messages of the kind (which is probably a follow-up error to the above):
2017-03-14 11:20:20,117 INFO [Blocking-Work-Executor-4] client.UaClient$a:? Got Bad_NoSubscription as a PublishResponse, although we have connected Subscriptions

As I understand the batch read my have some limitations, but ArrayIndexOutOfBoundsException suggests, there is some error in the processing of the client.
How to proceed?
We figured out the build info: manufacturer=SIEMENS AG, product=SIMATIC S7-1500 OPC UA, version=V02.00.01

Edit:
we are using read(UaClient.MAX_CACHE_AGE, TimestampsToReturn.Neither, ReadValueId[]) – with attributes Attributes.DataType and Attributes.UserAccessLevel for UaVariables nodes only.

March 15, 2017
11:37, EET
Avatar
Jouni Aro
Moderator
Moderators
Forum Posts: 1026
Member Since:
December 21, 2011
sp_UserOfflineSmall Offline

Yes, we have seen this issue with the Siemens server already and there is a fix for it coming in the next release. If you wish you can contact uajava-support to get a beta version for verification.

March 15, 2017
16:00, EET
Avatar
in-fke
Member
Members
Forum Posts: 36
Member Since:
June 8, 2016
sp_UserOfflineSmall Offline

Thank you for confirming this. We contacted support.

March 29, 2017
17:39, EEST
Avatar
in-fke
Member
Members
Forum Posts: 36
Member Since:
June 8, 2016
sp_UserOfflineSmall Offline

We can confirm that with 2.2.7 (beta) the issue with the ArrayIndexOutOfBoundsException in the batch read is now gone.
This “Topic” may be considered closed.
Moving from browse / getNode to browse / read reduced our browsing time signigicantly.
For reference, our browsing routine for the PROSYS Simulation Server went from 15s down to 3s (client and server on the same machine).

But alas, we are now running into this problem on the S7-1500:
http://forum.prosysopc.com/for…..criptions/
I will continue on that thread.

April 18, 2017
15:46, EEST
Avatar
in-fke
Member
Members
Forum Posts: 36
Member Since:
June 8, 2016
sp_UserOfflineSmall Offline

Now that 2.3.0 is out: is this issue also fixed in 2.3.0? (it was fixed in 2.2.7) – could not find it in the release notes (or did I miss 2.2.8?)

April 18, 2017
18:43, EEST
Avatar
Jouni Aro
Moderator
Moderators
Forum Posts: 1026
Member Since:
December 21, 2011
sp_UserOfflineSmall Offline

Yes that is included in 2.3.0. Seems like it was considered so minor that it wasn’t added to the release notes…

Forum Timezone: Europe/Helsinki

Most Users Ever Online: 1919

Currently Online:
19 Guest(s)

Currently Browsing this Page:
1 Guest(s)

Top Posters:

Heikki Tahvanainen: 402

hbrackel: 144

rocket science: 88

pramanj: 86

Francesco Zambon: 83

Ibrahim: 78

Sabari: 62

kapsl: 57

gjevremovic: 49

Xavier: 43

Member Stats:

Guest Posters: 0

Members: 730

Moderators: 7

Admins: 1

Forum Stats:

Groups: 3

Forums: 15

Topics: 1529

Posts: 6471

Newest Members:

toneylapham544, rondawolinski7, Marypof5711, roycedelargie91, kourtneyquisenbe, ellis87832073466, zkxwilliemae, gabriellabachus, Deakin, KTP25Zof

Moderators: Jouni Aro: 1026, Pyry: 1, Petri: 0, Bjarne Boström: 1032, Jimmy Ni: 26, Matti Siponen: 349, Lusetti: 0

Administrators: admin: 1