Avatar

Please consider registering
guest

sp_LogInOut Log In sp_Registration Register

Register | Lost password?
sp_Search Search
Advanced Search
Advanced Search

— Forum Scope —




— Match —





— Forum Options —





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

sp_Search Search
Go to Bottom
No permission to create posts
sp_Feed Topic RSS sp_TopicIcon
Doing time consuming stuff in onDataChange of a subscription prevents onDataChange of another subscription
June 19, 2020
17:58, EEST
Avatar
rocket science
Member
Members
Forum Posts: 77
Member Since:
March 16, 2017
sp_UserOfflineSmall Offline
Go to Top
1sp_EditHistory sp_Permalink sp_Print

Hi,

I observed, that when I do some time consuming action in the onDataChange of a monitored item in a subscription, it prevents all other onDataChanges even from monitored items from other subscriptions from getting triggered.

Here’s the overview of the scenario:
I have 2 subscription.
Each subscription has one monitored item.
Each monitored item has it’s own MonitoredDataItemListener.

To test it I’m using the Prosys Simulation Server (Subscription 1 has a monitored item on ‘Counter1’, Subscription 2 has a monitored item on ‘Expression1’)

In a normal case, I get onDataChanges each second for Counter1 and Expression 1.

But when I do some time consuming stuff in e.g. the onDataChange for Counter1, I do not get the onDataChanges for ‘Expression1’ from the Subscription 2 until the time consuming tuff done in onDataChange of ‘Counter1’ has completed.

I always thought, that onDataChanges of MonitoredItems of different subscriptions are not blocked by each other.

Is there any possibility to set or to configure something to get the notification of the Subscription 2 ?

I’ve made some example to reproduce the behaviour.
The example makes two subscriptions whith each subscription has it’s own monitored item using it’s own MonitoredDataItemListener.
On the 3rd data change of monitored item 1 (The Counter1) I do some time consuming stuff (a 5sec sleep) in the onDataChange.

In the logs I can see, that the onDataChanges for monitored item of subscription 2 are not reported to the client until the time consuming stuff was completed.

Here’s my test code:

{code}
@Test
public void testSubscription()
throws Exception
{
/* 1st subscription */
LOGGER.info(“testSubscription() Create 1st Subscription”);
Subscription subscription1 = new Subscription();
LOGGER.info(“testSubscription() subscription1=” + subscription1);

MonitoredDataItem monitoredDataItem1 = new MonitoredDataItem(NodeId.get(IdType.String, _client.getNamespaceTable().getIndex(“http://www.prosysopc.com/OPCUA/SimulationNodes”), “Counter1”));
monitoredDataItem1.setDataChangeListener(new MonitoredDataItemListener() {

int i = 0;

@Override
public void onDataChange(MonitoredDataItem sender, DataValue prevValue, DataValue value) {
i++;
LOGGER.info(“MonitoredDataItemListener 1″ + ” testSubscription().onDataChange sender ” + sender);
LOGGER.info(“MonitoredDataItemListener 1″ + ” testSubscription().onDataChange value ” + value);
try {
if(i==3) {
// do some time consuming stuff
LOGGER.info(“MonitoredDataItemListener 1″ + ” testSubscription().onDataChange sleeping for 5secs”);
Thread.sleep(5000);
LOGGER.info(“MonitoredDataItemListener 1″ + ” testSubscription().onDataChange sleeping finished”);
}
}
catch (InterruptedException e) {}
}
});
subscription1.addItem(monitoredDataItem1);
LOGGER.info(“testSubscription() monitoredDataItem1=” + monitoredDataItem1.toString());

/* 2nd subscription */
LOGGER.info(“testSubscription() Create 2nd Subscription”);
Subscription subscription2 = new Subscription();
LOGGER.info(“testSubscription() subscription2=” + subscription2);

MonitoredDataItem monitoredDataItem2 = new MonitoredDataItem(NodeId.get(IdType.String, _client.getNamespaceTable().getIndex(“http://www.prosysopc.com/OPCUA/SimulationNodes”), “Expression1”));
monitoredDataItem2.setDataChangeListener(new MonitoredDataItemListener() {
@Override
public void onDataChange(MonitoredDataItem sender, DataValue prevValue, DataValue value) {
LOGGER.info(“MonitoredDataItemListener 2″ + ” testSubscription().onDataChange sender ” + sender);
LOGGER.info(“MonitoredDataItemListener 2″ + ” testSubscription().onDataChange value ” + value);
}
});
subscription2.addItem(monitoredDataItem2);
LOGGER.info(“testSubscription() monitoredDataItem2=” + monitoredDataItem2);

/* Adding the subscriptions to the client object */

LOGGER.info(“testSubscription() Adding 1st Subscription”);
_client.addSubscription(subscription1);
LOGGER.info(“testSubscription() subscription1=” + subscription1);

LOGGER.info(“testSubscription() Adding 2nd Subscription”);
_client.addSubscription(subscription2);
LOGGER.info(“testSubscription() subscription2=” + subscription2);

// wait for user input to stop
BufferedReader stdin = new BufferedReader(new InputStreamReader(System.in));
String s = stdin.readLine();
LOGGER.info(“testSubscription() exit”);
}
{code}

And here’s the corresponding log:

2020-06-19 15:09:45,042|INFO |org.opcfoundation.ua.transport.tcp.io.TcpConnection|/127.0.0.1:53530 Connecting
2020-06-19 15:09:45,049|INFO |org.opcfoundation.ua.transport.tcp.io.TcpConnection|/127.0.0.1:53530 Connected

/* I create the two subscriptions */

2020-06-19 15:09:46,212|INFO |testSubscription() Create 1st Subscription
2020-06-19 15:09:46,218|INFO |testSubscription() subscription1=Subscription id=null PublishingInterval=1000.0 isPublishingEnabled=true priority=0 lifetimeCount=60 maxKeepAliveCount=20 maxNotificationsPerPublish=0
2020-06-19 15:09:46,222|INFO |testSubscription() monitoredDataItem1=ClientHandle=1, MonitoredItemId=null, NodeId=ns=5;s=Counter1, AttributeId=Value

2020-06-19 15:09:46,222|INFO |testSubscription() Create 2nd Subscription
2020-06-19 15:09:46,223|INFO |testSubscription() subscription2=Subscription id=null PublishingInterval=1000.0 isPublishingEnabled=true priority=0 lifetimeCount=60 maxKeepAliveCount=20 maxNotificationsPerPublish=0
2020-06-19 15:09:46,223|INFO |testSubscription() monitoredDataItem2=ClientHandle=2, MonitoredItemId=null, NodeId=ns=5;s=Expression1, AttributeId=Value

/* Adding the subscription to the UaClient */

2020-06-19 15:09:46,224|INFO |testSubscription() Adding 1st Subscription
2020-06-19 15:09:46,250|INFO |testSubscription() subscription1=Subscription id=30 PublishingInterval=1000.0 isPublishingEnabled=true priority=0 lifetimeCount=60 maxKeepAliveCount=20 maxNotificationsPerPublish=0
2020-06-19 15:09:46,250|INFO |testSubscription() Adding 2nd Subscription
2020-06-19 15:09:46,270|INFO |testSubscription() subscription2=Subscription id=31 PublishingInterval=1000.0 isPublishingEnabled=true priority=0 lifetimeCount=60 maxKeepAliveCount=20 maxNotificationsPerPublish=0

/* When doing nothing in the onDataChange, everthing is fine
* I get onDataChange for the monitored items of each subscription */

2020-06-19 15:09:47,233|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:47,234|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=92, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:47.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:47,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:47,259|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=-0.01347331561243914, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:47.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)

2020-06-19 15:09:48,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:48,231|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=94, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:48.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:48,257|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:48,257|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=0.02442954980637113, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:48.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)

/* No I start to to some time consuming stuff -> a sleep by 5sec
*/

2020-06-19 15:09:49,239|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:49,241|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=96, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:49.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:49,241|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sleeping for 5secs
2020-06-19 15:09:54,242|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sleeping finished

/* I expected to get the onDataChanges of ‘Subscription 2’ during this 5 seconds, but for the 5
seconds, I do not get any onDataChange from Subscription 2 */

/* After the time consuming stuff in the onDataChange of MonitoredItem from Subscription 1
is completed, I get 5x onDataChanges of Monitored Item of Subscription 1 and afterwards the
5x 5x onDataChanges of Monitored Item of Subscription 2
*/

2020-06-19 15:09:54,242|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:54,242|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=98, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:50.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,242|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:54,242|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=100, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:51.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,243|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:54,243|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=1, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:52.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,243|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:54,243|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=3, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:53.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,243|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:54,244|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=5, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:54.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)

2020-06-19 15:09:54,244|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:54,244|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=0.11371037063523137, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:49.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,244|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:54,245|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=0.26794924452492497, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:50.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,245|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:54,245|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=0.4978869721615593, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:51.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,245|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:54,245|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=0.8109561700334638, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:52.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,246|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:54,246|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=1.2109562497118682, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:53.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:54,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:54,259|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=1.697886973463879, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:54.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)

2020-06-19 15:09:55,229|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:55,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=7, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:55.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:55,259|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:55,259|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=-1.7320508305217501, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:55.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:56,234|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:56,235|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=9, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:56.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:56,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:56,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=-1.0862896977139518, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:56.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:57,236|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:57,237|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=11, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:57.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:57,257|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:57,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=-0.37557057054678733, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:57.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:58,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:58,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=13, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:58.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:58,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:58,259|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=0.3865267515410027, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:58.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:59,229|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:09:59,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=15, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:59.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:09:59,265|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:09:59,265|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=1.1841766429103475, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:09:59.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:10:00,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:10:00,230|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=17, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:10:00.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:10:00,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:10:00,258|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=1.9999998931668175, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:10:00.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:10:01,238|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange sender ClientHandle=1, MonitoredItemId=1, NodeId=ns=5;s=Counter1, AttributeId=Value
2020-06-19 15:10:01,239|INFO |MonitoredDataItemListener 1 testSubscription().onDataChange value DataValue(value=19, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:10:01.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
2020-06-19 15:10:01,262|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange sender ClientHandle=2, MonitoredItemId=1, NodeId=ns=5;s=Expression1, AttributeId=Value
2020-06-19 15:10:01,262|INFO |MonitoredDataItemListener 2 testSubscription().onDataChange value DataValue(value=2.8158232646966903, statusCode=GOOD (0x00000000) “”, sourceTimestamp=06/19/20 13:10:01.0000000 GMT, sourcePicoseconds=0, serverTimestamp=null, serverPicoseconds=0)
x
2020-06-19 15:10:01,430|INFO |testSubscription() exit
2020-06-19 15:10:01,443|INFO |com.prosysopc.ua.client.UaClient$a |Got Bad_NoSubscription as a PublishResponse, although we have connected Subscriptions
2020-06-19 15:10:01,461|INFO |org.opcfoundation.ua.transport.tcp.io.SecureChannelTcp|84 Closed
2020-06-19 15:10:01,462|INFO |org.opcfoundation.ua.transport.tcp.io.TcpConnection |/127.0.0.1:53530 Closed
2020-06-19 15:10:01,462|INFO |org.opcfoundation.ua.transport.tcp.io.TcpConnection |/127.0.0.1:53530 Closed (expected)

June 22, 2020
14:13, EEST
Avatar
Matti Siponen
Moderator
Members

Moderators
Forum Posts: 321
Member Since:
February 11, 2020
sp_UserOfflineSmall Offline
Go to Top
2sp_Permalink sp_Print

Hello,

UaClient periodically checks each Subscription for queued PublishResponses. Each PublishResponse is then checked for DataChange Notifications. Each DataChange Notification is then processed to set the Value of the corresponding Monitored Data Item. If the Value changes, onDataChange methods of associated MonitoredDataItemListeners are called.

This Subscription handling process is done in a predetermined order, which could be described as nested for-each loops. The outer loop is for Subscriptions, the middle loop is for PublishResponses and the inner loop is for DataChange Notifications. While this approach works well enough, it’s not perfectly safe as Subscriptions can face resource starvation if processing a PublishResponse takes longer than receiving a new PublishResponse as the loop won’t move on to the next Subscription as long as there are queued PublishResponses.

In your scenario, when the 3rd PublishResponse arrives for Subscription 1 and forces the onDataChange method to sleep for 5 seconds, five more PublishResponses are queued to both of your Subscriptions. After the sleep, Subscription 1 is still being processed and thus the five additional queued PublishResponses are processed one by one. After there are no more queued PublishResponses to Subscription 1, the six queued PublishResponses of Subscription 2 are processed one by one. After catching up, UaClient now has sufficient time to process PublishResponses to both Subscriptions in the order they’re received as shown by the last part of your log.

In short, calling onDataChange methods block the processing of DataChange Notifications, PublishResponses and Subscriptions until the called method has finished its execution. If you need to perform a time consuming operation in onDataChange method, you should have this method create a Thread or pass the necessary data to an already running Thread to perform this operation on the background and avoid blocking the Subscription handling process.

June 22, 2020
16:25, EEST
Avatar
rocket science
Member
Members
Forum Posts: 77
Member Since:
March 16, 2017
sp_UserOfflineSmall Offline
Go to Top
3sp_Permalink sp_Print

Hi,

thank you for the detailed explanation.

I’ll think I will pass the onDataChange handling for each subscription to an own thread executor, so that my onDataChanges of the monitored items of subscription 1 or no more blocking the onDataChanges of my the monitored items of subscription 2.

Thank you!

No permission to create posts
sp_Feed All RSS
Go to top
Forum Timezone: Europe/Helsinki

Most Users Ever Online: 518

Currently Online:
17 Guest(s)

Currently Browsing this Page:
1 Guest(s)

Top Posters:

hbrackel: 135

pramanj: 86

Francesco Zambon: 81

rocket science: 77

ibrahim: 75

Sabari: 62

kapsl: 57

gjevremovic: 49

Xavier: 43

fred: 41

Member Stats:

Guest Posters: 0

Members: 685

Moderators: 16

Admins: 1

Forum Stats:

Groups: 3

Forums: 15

Topics: 1467

Posts: 6259

Newest Members:

fidelduke938316, Jan-Pfizer, DavidROunc, fen.pang@woodside.com, aytule, rashadbrownrigg, christi10l, ahamad1, Flores Frederick, ellenmoss

Moderators: Jouni Aro: 1009, Otso Palonen: 32, Tuomas Hiltunen: 5, Pyry: 1, Petri: 0, Bjarne Boström: 983, Heikki Tahvanainen: 402, Jukka Asikainen: 1, moldzh08: 0, Jimmy Ni: 26, Teppo Uimonen: 21, Markus Johansson: 42, Niklas Nurminen: 0, Matti Siponen: 321, Lusetti: 0, Ari-Pekka Soikkeli: 5

Administrators: admin: 1